No Huddle Offense

"Individual commitment to a group effort-that is what makes a team work, a company work, a society work, a civilization work."

Python & DTrace

July 1st, 2011 • Comments Off on Python & DTrace

The following DTrace script can be used to trace Python. It will show you the file, line-number, the time it took to get from the last line to the current one and the (indented) function it is in. This helps understanding the flow of your Python code and can help finding bugs & timing issues. As a little extra it is setup the way that it only shows the files of your code – not the once located in /usr/lib/*. This helps with readability and makes the output more dense since the site-packages are left out.

I now have this running in the background on a second screen whenever I code python. First screen holds my IDE – and next to all the other stuff I do it gives great up-to-date information on the stuff you’re coding. Again proof for the case that coding Python on Solaris is a great idea (Also thanks to DTrace). I know this is simple stuff – but sometimes the simple stuff helps a lot! Now it would only be nice to create a GUI around it šŸ™‚ First the DTrace script is shown; example output is further below…

#pragma D option quiet

self int depth;
self int last;

dtrace:::BEGIN
{
    printf("Tracing... Hit Ctrl-C to end.\n");
    printf(" %-70s %4s %10s : %s %s\n", "FILE", "LINE", "TIME",
           "FUNCTION NAME", "");
}

python*:::function-entry,
python*:::function-return
/ self->last == 0 /
{
    self->last = timestamp;
}

python*:::function-entry
/ dirname(copyinstr(arg0)) <= "/usr/lib/" /
{
    self->delta = (timestamp - self->last) / 1000;
    printf(" %-70s %4i %10i : %*s> %s\n", copyinstr(arg0), arg2, self->delta,
           self->depth, "", copyinstr(arg1));
    self-> depth++;
    self->last = timestamp;
}

python*:::function-return
/ dirname(copyinstr(arg0)) <= "/usr/lib/" /
{
    self->delta = (timestamp - self->last) / 1000;
    self->depth--;
    printf(" %-70s %4i %10i : %*s< %s\n", copyinstr(arg0), arg2, self->delta,
            self->depth, "", copyinstr(arg1));
    self->last = timestamp;
}

Example output:

 $ pfexec dtrace -s misc/py_trace.d
Tracing... Hit Ctrl-C to end.
 FILE                                                                   LINE       TIME : FUNCTION NAME 
[...]
 /home/tmetsch/data/workspace/pyssf/occi/service.py                      144       1380 : > put
 /home/tmetsch/data/workspace/pyssf/occi/service.py                      184         13 :  > parse_incoming
 /home/tmetsch/data/workspace/pyssf/occi/service.py                       47          9 :   > extract_http_data
 /home/tmetsch/data/workspace/pyssf/occi/service.py                       68         39 :   < extract_http_data
 /home/tmetsch/data/workspace/pyssf/occi/service.py                       70         10 :   > get_parser
 /home/tmetsch/data/workspace/pyssf/occi/registry.py                      60         36 :    > get_parser
 /home/tmetsch/data/workspace/pyssf/occi/registry.py                      83         12 :    < get_parser
 /home/tmetsch/data/workspace/pyssf/occi/service.py                       77          8 :   < get_parser
 /home/tmetsch/data/workspace/pyssf/occi/protocol/rendering.py            99         11 :   > to_entity
 /home/tmetsch/data/workspace/pyssf/occi/protocol/rendering.py            81         10 :    > extract_data
 /home/tmetsch/data/workspace/pyssf/occi/protocol/rendering.py            37         11 :     > __init__
 /home/tmetsch/data/workspace/pyssf/occi/protocol/rendering.py            41         11 :     < __init__
 /home/tmetsch/data/workspace/pyssf/occi/protocol/rendering.py            97         14 :    < extract_data
[...]

This was inspired by the py_flowtime.d script written by Brendan Gregg.

Comments are closed.