How does a tracer work?
Originally, I wanted this post to be about writing a debugger, as I’m working on one in noWorkflow. However, the post was getting bigger and bigger, and instead of writing about a debugger, I decided to write about a tracer.
A tracer is a way to inject code into Python to watch what the interpreter is doing at low-level. According to the documentation, it is intended to allow the implementation of a Python debugger using Python. However, there are many other uses: coverage.py uses it to track line coverage; noWorkflow uses it to perform dynamic program slicing; line_profiler uses it to profile each line execution.
So, in this post I will talk about how to implement a tracer and how does it work.
Defining a tracer
The easiest way to define a tracer is to define a trace function and pass it to sys.settrace. A trace function is a function that receives three arguments (frame, event and arg): frame represents the current stack frame; event indicates if Python is executing a ‘line’, a function ‘call’, a function ‘return’ or an ‘exception’; and arg represents an optional extra argument that can be either an exception information or a function return value.
Let’s define a simple tracer that only prints out the current line number, and the received event and arg.
import sys
def py_trace_function(frame, event, arg):
print(frame.f_lineno, event, arg)
def last(x):
return x[-1]
def fifth_or_last(lis):
lis.append(4)
try:
result = lis[5]
except IndexError:
result = last(lis)
return result
sys.settrace(py_trace_function)
a = fifth_or_last([1, 2])
a += 2
c = last([5, 6])
The result of this code is
9 call None 6 call None 6 call None
Note that it only captured ‘call’ events. More specifically, it only captured fifth_or_last([1, 2]), on line 19, last(lis) on line 14, and last([5, 6]) on line 21.
Understanding the settrace
Why didn’t it capture ‘line’, ‘exception’ and ‘return’ events? To explain why did it happen, we must look at the sys.settrace implementation. It is implemented in C at /Python/sysmodule.c
// <PythonSrc>/Python/sysmodule.c
// Line numbers do not represent the actual file
static PyMethodDef sys_methods[] = {
...
{"settrace", sys_settrace, METH_O, settrace_doc},
...
};
static PyObject *
sys_settrace(PyObject *self, PyObject *args)
{
if (trace_init() == -1)
return NULL;
if (args == Py_None)
PyEval_SetTrace(NULL, NULL);
else
PyEval_SetTrace(trace_trampoline, args);
Py_INCREF(Py_None);
return Py_None;
}
In line 6, we can see that the settrace method is implemented by the function sys_settrace. This function first calls trace_init() to cache event strings (not represented here), then invokes PyEval_SetTrace passing the C function trace_trampoline and our py_trace_function as parameter.
PyEval_SetTrace is implemented at /Python/ceval.c. I won’t show it here, but it basically sets some thread state variables to activate the tracing: tstate->c_tracefunc gets trace_trampoline and tstate->c_traceobj gets py_trace_function. It means that the tracing is specific to a single thread. It is necessary to invoke sys.settrace multiple times to trace multiple threads.
During the execution of the bytecode, the interpreter calls the function call_trace if the tracing is active. The interpreter passes trace_trampoline as func argument, py_trace_function as obj argument, thread state as tstate argument, the current frame as frame argument, the event type (line, call, return, exception) as what argument, and arg as arg argument.
// <PythonSrc>/Python/ceval.c
// Line numbers do not represent the actual file
static int
call_trace(Py_tracefunc func, PyObject *obj,
PyThreadState *tstate, PyFrameObject *frame,
int what, PyObject *arg)
{
int result;
if (tstate->tracing)
return 0;
tstate->tracing++;
tstate->use_tracing = 0;
result = func(obj, frame, what, arg);
tstate->use_tracing = ((tstate->c_tracefunc != NULL)
|| (tstate->c_profilefunc != NULL));
tstate->tracing--;
return result;
}
This function basically disables the tracing temporally, propagates the passed arguments to trace_trampoline (with the exception of thread state variable), reactivates the tracing (if c_tracefunc is still set) and returns the trace_trampoline result. The disabling is necessary to avoid an infinite recursion of tracing the py_trace_function
Let’s look at trace_trampoline now:
// <PythonSrc>/Python/sysmodule.c
// Line numbers do not represent the actual file
static int
trace_trampoline(PyObject *self, PyFrameObject *frame,
int what, PyObject *arg)
{
PyObject *callback;
PyObject *result;
if (what == PyTrace_CALL)
callback = self;
else
callback = frame->f_trace;
if (callback == NULL)
return 0;
result = call_trampoline(callback, frame, what, arg);
if (result == NULL) {
PyEval_SetTrace(NULL, NULL);
Py_CLEAR(frame->f_trace);
return -1;
}
if (result != Py_None) {
PyObject *temp = frame->f_trace;
frame->f_trace = NULL;
Py_XDECREF(temp);
frame->f_trace = result;
}
else {
Py_DECREF(result);
}
return 0;
}
Reading this function, we can see that if the event (what) is ‘call’ (PyTrace_CALL), the callback is automatically set to self (py_trace_function). Otherwise, it will be set to frame->f_trace.
Then, the result of the function will be the result of call_trampoline, that just invokes the python function (py_trace_function) and returns its result.
If the result is NULL (None in Python), tracing will stop. Otherwise, the new tracing function will be the result of py_trace_function.
Fixing our tracer
So, if we want to propagate the tracing, we must return a tracing function in the py_trace_function. It can be the py_trace_function itself:
def py_trace_function(frame, event, arg):
print(frame.f_lineno, event, arg)
return py_trace_function
In this case, the result will be:
10 call None
11 line None
12 line None
13 line None
13 exception (<class 'IndexError'>, IndexError('list index out of range',), <traceback object at 0x7f61fdc492c8>)
14 line None
15 line None
7 call None
8 line None
8 return 4
16 line None
16 return 4
7 call None
8 line None
8 return 6
It is much better than the previous result. Note, however, that it only captures ‘line’ events inside calls, and for some applications (such as debuggers), we need to have access to events that happen in the same level.
To fix that, we will use a workaround to set f_trace in the current frame:
sys._getframe().f_trace = py_trace_function sys.settrace(py_trace_function) a = fifth_or_last([1, 2]) a += 2 c = last([5, 6])
The result is complete now (with an extra return that represents the end of the script):
20 line None
10 call None
11 line None
12 line None
13 line None
13 exception (<class 'IndexError'>, IndexError('list index out of range',), <traceback object at 0x7f34e1fb7348>)
14 line None
15 line None
7 call None
8 line None
8 return 4
16 line None
16 return 4
21 line None
22 line None
7 call None
8 line None
8 return 6
22 return None
Our workaround activates the tracer in the current frame. What happens if we extract lines 18 and 19 to a function? In this case, the current frame will be the function frame.
import sys
def py_trace_function(frame, event, arg):
print(frame.f_lineno, event, arg)
return py_trace_function
def set_trace():
sys._getframe().f_trace = py_trace_function
sys.settrace(py_trace_function)
def last(x):
return x[-1]
def fifth_or_last(lis):
lis.append(4)
try:
result = lis[5]
except IndexError:
result = last(lis)
return result
set_trace()
a = fifth_or_last([1, 2])
a += 2
c = last([5, 6])
As we do not set f_trace to the __main__ frame anymore, it stops tracing outer level lines. Note that it keeps tracing calls and lines inside calls, because trace_trampoline automatically sets py_trace_function as callback when the event is call:
18 line None 19 line None 11 call None 12 line None 12 return 4 20 line None 20 return 4 11 call None 12 line None 12 return 6
To fix this problem, we need to go back a frame, and set its f_trace:
def set_trace():
frame = sys._getframe().f_back # caller frame
frame.f_trace = py_trace_function
sys.settrace(py_trace_function)
This fixes the issue (do I need to repeat the results?), but highlights another one: what if we want to activate the tracing inside a function and capture up to the end of file:
import sys
def py_trace_function(frame, event, arg):
print(frame.f_lineno, event, arg)
return py_trace_function
def set_trace():
frame = sys._getframe().f_back # caller frame
frame.f_trace = py_trace_function
sys.settrace(py_trace_function)
def last(x):
return x[-1]
def fifth_or_last(lis):
lis.append(4)
set_trace()
try:
result = lis[5]
except IndexError:
result = last(lis)
return result
a = fifth_or_last([1, 2])
a += 2
c = last([5, 6])
The result is:
20 line None 21 line None 12 call None 13 line None 13 return 4 22 line None 22 return 4 12 call None 13 line None 13 return 6
Quite incomplete, right? To fix it, the default operation (as implemented in /Lib/bdb.py is to navigate the frames and set f_trace to all of them.
Complete tracer
The resulting tracer is:
def py_trace_function(frame, event, arg):
print(frame.f_lineno, event, arg)
return py_trace_function
def set_trace():
frame = sys._getframe().f_back # caller frame
while frame:
frame.f_trace = py_trace_function
frame = frame.f_back
sys.settrace(py_trace_function)
And it does work fine:
20 line None
21 line None
21 exception (<class 'IndexError'>, IndexError('list index out of range',), <traceback object at 0x7fbb3472a408>)
22 line None
23 line None
14 call None
15 line None
15 return 4
24 line None
24 return 4
27 line None
28 line None
14 call None
15 line None
15 return 6
28 return None
Executing tracer for the whole script
For now, if we want to use the tracer, we need to invoke the function set_trace. However it is not necessarily true if we want to execute a script with the tracer active from the beginning. To do so, we can use the sys.settrace (capturing only calls) and invoke the desired script by eval, which will be a call:
import sys
def py_trace_function(frame, event, arg):
print(frame.f_lineno, event, arg)
return py_trace_function
def set_trace():
frame = sys._getframe().f_back # caller frame
while frame:
frame.f_trace = py_trace_function
frame = frame.f_back
sys.settrace(py_trace_function)
if __name__ == '__main__':
path = ' '.join(sys.argv[1:])
namespace = {
'__name__' : '__main__',
'__file__' : path,
'__builtins__': __builtins__,
}
compiled = compile(open(path).read(), path, 'exec')
sys.settrace(py_trace_function)
eval(compiled, namespace)
By running $ python tracer.py example.py, we will get the full trace:
1 call None
1 line None
4 line None
12 line None
4 call None
5 line None
6 line None
7 line None
7 exception (<class 'IndexError'>, IndexError('list index out of range',), <traceback object at 0x7f8a5d08bc88>)
8 line None
9 line None
1 call None
2 line None
2 return 4
10 line None
10 return 4
13 line None
14 line None
1 call None
2 line None
2 return 6
14 return None
Conclusions
I presented a small tracer that can be expanded to perform more complex things. We looked at the tracing implementation of CPython to understand how does it work and how to implement tracers in Python. It is worthy highlighting some points:
- A tracer is a way to inject code that watches the execution
- Tracers are specific to threads. They must be activated individually for each thread
- CPython activates the tracer specified by sys.settrace only for ‘call’ events. It requires the trace function to return a trace function in order to propagate the tracer
- It is necessary to manually set f_trace if want to execute the full tracer in the current or previous frame
If you what to learn more about tracers, I suggest reading the Python Module of the Week page and its references
Leave a Reply