Python & DTrace
July 1st, 2011 • Comments Off on Python & DTraceThe 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.