Binu Jose Philip's Weblog

DTrace provider for Python

Many scripting languages and their uncles (and some aunties) are
getting dtrace-able these days. Being a Python believer, the lack of
dtrace for Python seemed .. a lack. Either very few Solaris (and other
dtrace enabled patform) users like Python or Python is easy enough to
debug and tune without needing DTrace ;-)

I convinced myself of the need mainly due to needling by colleagues.
Perl aficionados, PHP purists, Ruby upstarts and what not. The other
factor was the overhead introduced by DTrace when probes are activated
and other-wise. It is negligible! We don't pay any tax for having it
in there. So why not? Since I hadn't attempted a similar something
before nor looked at the insides of an interpreter for geological
times, I was apprehensive. After seeing this, I decided Python shouldn't 
loose any of the possible visibility.

I was impeded mainly by Thud! and Ilium. Now that I have finished 
Olympos I am free to PyDTrace and blog about it.

The changes are small, here are the unified diffs. After applying the
diffs, give a "--enable-dtrace" to configure. The only two probes
available are function 'entry' and function 'exit'. The nice part is,
if you feel the need to extend it - say probe every attribute store -
it is extremely simple to do. You would need only to modify
Python/ceval.c around "STORE_ATTR:" of the interpreter loop and
Python/pydtrace.d to add the new probe description.

One problem I faced and is still facing is compiling for sparc
necessitates using the v7 instruction set, else dtrace fails saying
wrong machine class. dtrace expects sparc ELFs to be compiled for v7
looks like. I am on s10 FCS for various reasons and didn't want to ask
before trying out the oozing edge builds. I am excluding my idiotic
antics because I tried to dtrace scripts launched via '#!/usr/bin/env
python' and ended up trying to dtrace the non-existant env process.

Here is what is possible with PyDTrace. The file pydtrace.d will tell
you the arguments available with each probe.


test.py

#!/usr/local/bin/python

import sys

def a():
    print "Ah! death. Welcome to thee brother"
    sys.exit()

def b():
    print "Where art thou a()?"
    a()

def c():
    print "The band of alphabets"
    b()

def main():
    c()

if __name__ == "__main__":
    main()
    

test.d

#pragma D option quiet

python$target:::
{
	printf("%s\n", copyinstr(arg1));
}

# dtrace -s test.d -c test.py

The band of alphabets
Where art thou a()?
Ah! death. Welcome to thee brother
<module>
_get_exports_list
_get_exports_list
<module>

[..snip..]

search_function
<module>
main
c
b
a
a
b
c
main
<module>



Ooh, too much. We don't want trace every library call. Let's take
advantage of them being loaded from /usr/local/lib/...somewhere and
one of the probe args being the file-name. We'l also use entry and
exit probes this time.


test.d

#pragma D option quiet

python$target:::entry
/stringof(copyin(arg0, 14)) != "/usr/local/lib"/
{
	printf("=> %s %s\n", copyinstr(arg1), copyinstr(arg0));
	self->traced = 1
}

python$target:::exit
/self->traced/
{
	printf("<= %s\n", copyinstr(arg1));
	self->traced = 0
}


# dtrace -s test.d -c test.py
The band of alphabets
Where art thou a()?
Ah! death. Welcome to thee brother
=> <module> /home/bp90447/projs/pydtrace/test.py
=> main /home/bp90447/projs/pydtrace/test.py
=> c /home/bp90447/projs/pydtrace/test.py
=> b /home/bp90447/projs/pydtrace/test.py
=> a /home/bp90447/projs/pydtrace/test.py
<= a



That's better. Let's try it on something bigger. I had an SMF
dependancy visulization thingy that I blogged about earlier. Let's
try timing the functions in there.


test.d

#pragma D option quiet

python$target:::entry
/stringof(copyin(arg0, 14)) != "/usr/local/lib"/
{
	self->ts=timestamp;
	self->traced = 1;
}

python$target:::exit
/self->traced/
{
	self->elapsed = timestamp - self->ts;
	@time[copyinstr(arg1)]=sum(self->elapsed);
}


# dtrace -s test.d -c ~xxxx/projs/svc-graph/svcgraf.py\ gss
Creating service instance for svc:/network/rpc/gss:default ... done.
Dependancy chain ...
----------------------------------------
                                  [ metainit ]
                               [ mpxio-upgrade ]
                         [ root manifest-import pfil ]
[...snip...]
                       [ multi-user-server dhcp-server ]
                                   [ zones ]
----------------------------------------
I had trouble initializing pygtk and/or talking to X. Check if pygtk
is available to python and if your DISPLAY variable is set to a sane
value

  get_one_name                                                  21333
  get_forward                                                   34416
  get_backward                                                  34917
  assign_bounds                                                 99251
  sort_it_out                                                  336999

[...snip...]

  find_dependancy_type                                     1076364984
  _compile                                                 1444167386
  extract_dependencies                                     2490782831
  getstatusoutput                                          7284394250



Wow! getstatusoutput() is hogging everything. But the 'wow!' is for
this working already. As a last demo piece let's see what other
arguments the exit probe exposes.

From pydtrace.d
...
Exit
	1. string (file name, f->f_code->co_filename->ob_sval)
	2. string (function name, f->f_code->co_name->ob_sval)
	3. string (object type string , object->ob_type->tp_name)
...

Let's see what "extract_dependencies" returns for this.


test.d

#pragma D option quiet

python$target:::entry
/stringof(copyin(arg0, 14)) != "/usr/local/lib"/
{
	self->ts=timestamp;
	self->traced = 1;
}

python$target:::exit
/self->traced/
{
	self->elapsed = timestamp - self->ts;
	@time[copyinstr(arg1)]=sum(self->elapsed);
}


python$target:::exit
/self->traced && copyinstr(arg1) == "extract_dependencies"/
{
	@returnvalue[copyinstr(arg2)]=count();
}

END {
	trunc(@time, 10);
	printf("\nTop functions by time");
	printa(@time);
	printf("\nReturn types for 'extract_dependencies'");
	printa(@returnvalue);
}


# dtrace -s test.d -c ~xxxx/projs/svc-graph/svcgraf.py\ gss
Creating service instance for svc:/network/rpc/gss:default ... done.
Dependancy chain ...
----------------------------------------
                                  [ metainit ]
                               [ mpxio-upgrade ]
[...snip...]
                       [ multi-user-server dhcp-server ]
                                   [ zones ]
----------------------------------------
I had trouble initializing pygtk and/or talking to X. Check if pygtk
is available to python and if your DISPLAY variable is set to a sane
value

Top functions by time
  get                                                       145876010
  __len__                                                   155688505
  _compile_charset                                          192261669
  __next                                                    308277021
  _parse                                                    481016701
  getwidth                                                  631352428
  find_dependancy_type                                     1010549659
  _compile                                                 1586552857
  extract_dependencies                                     2606270498
  getstatusoutput                                          7369136837

Return types for 'extract_dependencies'
  list                                                             39
  tuple                                                            39



There you have, DyPTrace. Oh! PyDTrace. If I feel the urge and no one
else feels it till then, I'l do something more comprehensive and
elaborate and functional and intergrated. That must be better than "I
don't feel like doing anything more on this now.".