« Previous day (May 9, 2005) | Main | Next day (May 10, 2005) »
Tuesday May 10, 2005

Beer, python and stuff

Question asked on the dtrace forums about adding dtrace probes to python. Following Bart's example and the docs, heres YAE (Yet Another Example) on adding dtrace functionality to an application.

This really is probably an example of where one shouldn't really use dtrace. See down at the end why.

First off, what do we want to look at from the application that dtrace can't already give us ? Well python is an interpeted language(?) so lets try and show what functions from a python script are being called. (this can already be done without modifying python's source code, though I'm too lazy to go figuring out the PyObject* structures, this is easier or is it right?).

Quickly browsing the code, looks like theres the fast_function function that can call script functions. Seems like as good as place as any to place a dtrace probe. The source file is Python/ceval.c. Adding a simple probe at the start of this to have the line number and script function name: 

..
..
PyObject *
fast_function(PyObject *func, PyObject ***pp_stack, int n, int na, int nk)
{
        PyCodeObject *co = (PyCodeObject *)PyFunction_GET_CODE(func);
        PyObject *globals = PyFunction_GET_GLOBALS(func);
        PyObject *argdefs = PyFunction_GET_DEFAULTS(func);
        PyObject **d = NULL;
        int nd = 0;

#ifdef HAVE_DTRACE
        DTRACE_PROBE2(python, pythond__2,
                co->co_firstlineno, PyString_AS_STRING(co->co_name));
#endif

        PCALL(PCALL_FUNCTION);
        PCALL(PCALL_FAST_FUNCTION);
..
..
Then create the dtrace provider script, Python/pythond.d: 

provider python {
        probe pythond__2(int, string);
};
Thats all. A few tweaks to the Makefile for compiling the dtrace script like: 
Python/pythond.o: $(srcdir)/Python/pythond.d $(PYTHON_OBJS) $(OBJECT_OBJS)
        /usr/sbin/dtrace -G -32 -o $@ -s $(srcdir)/Python/pythond.d $(PYTHON_OBJS)
Compile it up and give it a roll. 
Python-2.4.1/Demo/scripts# dtrace  -n 'python$target:::pythond-2' -c '../../python beer.py 1 '
dtrace: description 'python$target:::pythond-2' matched 1 probe
one bottle of beer on the wall,
one bottle of beer.
Take one down, pass it around,
no more bottles of beer on the wall.
dtrace: pid 1158 has exited
CPU     ID                    FUNCTION:NAME
  0  37700          fast_function:pythond-2
.
.
.
Python-2.4.1/Demo/scripts#
Right, the probe gets fired, a lot. Probably cause I haven't installed and compiled all the installable python scripts into python bytecode.

Lets see what I'm calling. 

Python-2.4.1/Demo/scripts# dtrace -o beer.out -n 'python$target:::pythond-2{@[stringof(copyinstr(arg1)), arg0]=count();}' -c '../../python beer.py 200' > /dev/null
dtrace: description 'python$target:::pythond-2' matched 1 probe
dtrace: pid 1172 has exited
Python-2.4.1/Demo/scripts#
Looking through the output file, beer.out, I see the script function 'bottle' being called 600 times from line number 6: 
.
.
.
  getwidth                                                        140               15
  fixup                                                            46               22
  isident                                                         210               25
  match                                                           195               53
  get                                                             201              283
  __next                                                          182              313
  bottle                                                            6              600
Sure enough the script function, bottle, is at line number 6. Similarly the script function, match, is at line 195 from the file Lib/sre_parse.py. 
Python-2.4.1$ grep -n 'def match(' Lib/*.py | grep '^195'
sre_parse.py:195:    def match(self, char, skip=1):
Python-2.4.1$ grep -n bottle Demo/scripts/beer.py | grep '^6:'
6:def bottle(n):
Python-2.4.1$
This is cool, I could now go and find hotspots in any python script I have. Those who know the python code better could add in a probe for python bytecode scripts as well. I know there are the settrace and setprofile functions in python, but they're thread specific and could be cumbersome to use on a live system (or thats what I read from the python docs).

I need to do something like this for perl and shell.

A quick addition to the provider to be able to print the file of the script function gets me: 

# dtrace -o d1 -n 'python$target:::pythond-2{@[stringof(copyinstr(arg1)), stringof(copyinstr(arg2))]=count();}' -c '../pythonscripts/beer.py 300' 
..
..
  match         Python-2.4.1/Lib/sre_parse.py               53
  get           Python-2.4.1/Lib/sre_parse.py              283
  __next        Python-2.4.1/Lib/sre_parse.py              313
  bottle        scripts/beer.py                            900
So the bottle function from the file scripts/beer.py was called 900 times.

Ok, why you shouldn't really use dtrace here like this. All the info gathered here is passed to fast_function() within the first argument. Having a simpler dtrace script to delve into this structure to pull out the info is all thats needed. Something like: 

#!/usr/sbin/dtrace -s

#include "Python.h"

#include "compile.h"
#include "frameobject.h"
#include "eval.h"
#include "opcode.h"
#include "structmember.h"

PyCodeObject *co;

pid$target::fast_function:entry
{
        
        co = (PyCodeObject *)PyFunction_GET_CODE(arg0);
        printf("python: %d %s %s\n",
                co->co_firstlineno,
                PyString_AS_STRING(co->co_name),
                PyString_AS_STRING(co->co_filename));
}
This means having some of the python source code somewhere whenever this script is run. Or pull out the structs into the script it self. Fun and games.

Posted at 03:08PM May 10, 2005 by smg in Dtrace  |  Comments[1]