PyMOTW: sys, Part 5: Tracing Your Program As It Runs

By Doug Hellmann
November 8, 2009

Tracing Your Program As It Runs

There are two ways to inject code to watch your program run: tracing and profiling. They are similar, but intended for different purposes and so have different constraints. The easiest, but least efficient, way to monitor your program is through a trace hook, which can be used for writing a debugger, code coverage monitoring, or many other purposes.

The trace hook is modified by passing a callback function to sys.settrace(). The callback is passed three arguments, frame (the stack frame from the code being run), event (a string naming the type of notification), and arg (an event-specific value). There are 7 event types for different levels of information that occur as your program is being executed.

EventWhenarg value
'call'Before a function is executed.None
'line'Before a line is executed.None
'return'Before a function returns.The value being returned.
'exception'After an exception occurs.The (exception, value, traceback) tuple.
'c_call'Before a C function is called.The C function object.
'c_return'After a C function returns.None
'c_exception'After a C function throws an error.None

Tracing Function Calls

A call event is generated before every function call. The frame passed to the callback can be used to find out which function is being called and from where.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
#!/usr/bin/env python
# encoding: utf-8

import sys

def trace_calls(frame, event, arg):
    if event != 'call':
        return
    co = frame.f_code
    func_name = co.co_name
    if func_name == 'write':
        # Ignore write() calls from print statements
        return
    func_line_no = frame.f_lineno
    func_filename = co.co_filename
    caller = frame.f_back
    caller_line_no = caller.f_lineno
    caller_filename = caller.f_code.co_filename
    print 'Call to %s on line %s of %s from line %s of %s' % \
        (func_name, func_line_no, func_filename,
         caller_line_no, caller_filename)
    return

def b():
    print 'in b()'

def a():
    print 'in a()'
    b()

sys.settrace(trace_calls)
a()

This example ignores calls to write(), as used by print to write to sys.stdout.

$ python sys_settrace_call.py
Call to a on line 27 of sys_settrace_call.py from line 32 of sys_settrace_call.py
in a()
Call to b on line 24 of sys_settrace_call.py from line 29 of sys_settrace_call.py
in b()

Tracing Inside Functions

The trace hook can return a new hook to be used inside the new scope (the local trace function). It is possible, for instance, to control tracing to only run line-by-line within certain modules or functions.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
#!/usr/bin/env python
# encoding: utf-8

import sys

def trace_lines(frame, event, arg):
    if event != 'line':
        return
    co = frame.f_code
    func_name = co.co_name
    line_no = frame.f_lineno
    filename = co.co_filename
    print '  %s line %s' % (func_name, line_no)

def trace_calls(frame, event, arg):
    if event != 'call':
        return
    co = frame.f_code
    func_name = co.co_name
    if func_name == 'write':
        # Ignore write() calls from print statements
        return
    line_no = frame.f_lineno
    filename = co.co_filename
    print 'Call to %s on line %s of %s' % (func_name, line_no, filename)
    if func_name in TRACE_INTO:
        # Trace into this function
        return trace_lines
    return

def c(input):
    print 'input =', input
    print 'Leaving c()'

def b(arg):
    val = arg * 5
    c(val)
    print 'Leaving b()'

def a():
    b(2)
    print 'Leaving a()'
    
TRACE_INTO = ['b']

sys.settrace(trace_calls)
a()

Here the global list of functions is kept in the variable TRACE_INTO, so when trace_calls() runs it can return trace_lines() to enable tracing inside of b().

$ python sys_settrace_line.py
Call to a on line 40 of sys_settrace_line.py
Call to b on line 35 of sys_settrace_line.py
  b line 36
  b line 37
Call to c on line 31 of sys_settrace_line.py
input = 10
Leaving c()
  b line 38
Leaving b()
Leaving a()

Watching the Stack

Another useful way to use the hooks is to keep up with which functions are being called, and what their return values are. To monitor return values, watch for the return event.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
#!/usr/bin/env python
# encoding: utf-8

import sys

def trace_calls_and_returns(frame, event, arg):
    co = frame.f_code
    func_name = co.co_name
    if func_name == 'write':
        # Ignore write() calls from print statements
        return
    line_no = frame.f_lineno
    filename = co.co_filename
    if event == 'call':
        print 'Call to %s on line %s of %s' % (func_name, line_no, filename)
        return trace_calls_and_returns
    elif event == 'return':
        print '%s => %s' % (func_name, arg)
    return

def b():
    print 'in b()'
    return 'response_from_b '

def a():
    print 'in a()'
    val = b()
    return val * 2

sys.settrace(trace_calls_and_returns)
a()

The local trace function is used for watching returns, so we need to return trace_calls_and_returns when a function is called.

$ python sys_settrace_return.py
Call to a on line 25 of sys_settrace_return.py
in a()
Call to b on line 21 of sys_settrace_return.py
in b()
b => response_from_b
a => response_from_b response_from_b

Exception Propagation

Exceptions can be monitored by looking for the exception event in a local trace function. When an exception occurs, the trace hook is called with the (type, instance, traceback) triple passed as arg.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
#!/usr/bin/env python
# encoding: utf-8

import sys

def trace_exceptions(frame, event, arg):
    if event != 'exception':
        return
    co = frame.f_code
    func_name = co.co_name
    line_no = frame.f_lineno
    filename = co.co_filename
    exc_type, exc_value, exc_traceback = arg
    print 'Tracing exception: %s "%s" on line %s of %s' % \
        (exc_type.__name__, exc_value, line_no, func_name)

def trace_calls(frame, event, arg):
    if event != 'call':
        return
    co = frame.f_code
    func_name = co.co_name
    if func_name in TRACE_INTO:
        return trace_exceptions

def c():
    raise RuntimeError('generating exception in c()')

def b():
    c()
    print 'Leaving b()'

def a():
    b()
    print 'Leaving a()'
    
TRACE_INTO = ['a', 'b', 'c']

sys.settrace(trace_calls)
try:
    a()
except Exception, e:
    print 'Exception handler:', e

Take care to limit where the local function is applied because some of the internals of formatting error messages generate, and ignore, their own exceptions. Every exception is seen by the trace hook, whether the caller catches and ignores it or not.

$ python sys_settrace_exception.py
Tracing exception: RuntimeError "generating exception in c()" on line 26 of c
Tracing exception: RuntimeError "generating exception in c()" on line 29 of b
Tracing exception: RuntimeError "generating exception in c()" on line 33 of a
Exception handler: generating exception in c()

See also

profile
The profile module documentation shows how to use a ready-made profiler.
Types and Members
The descriptions of frame and code objects and their attributes.
Tracing python code
Another settrace() tutorial.
Wicked hack: Python bytecode tracing
Ned Batchelder’s experiments with tracing with more granularity than source line level.

PyMOTW Home

The canonical version of this article


You might also be interested in:

News Topics

Recommended for You

Got a Question?