Navigation

Tracing a Program As It Runs

There are two ways to inject code to watch a 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 a 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 will receive 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 a program is being executed.

Event When arg 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
Exception AttributeError: "'NoneType' object has no attribute 'f_lineno'" in <function _remove at 0x1004469b0> ignored
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 :cont:`TRACE_INTO`, so when trace_calls() runs it can return trace_lines() to enable tracing inside of b().

$ python sys_settrace_line.py
Exception TypeError: "argument of type 'NoneType' is not iterable" in <function _remove at 0x1004469b0> ignored
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()
Call to _remove on line 38 of /Users/dhellmann/Envs/pymotw-ja/bin/../lib/python2.7/_weakrefset.py

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 trace_calls_and_returns() needs to return a reference to itself when a function is called, so the return value can be monitored.

$ 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
Call to _remove on line 38 of /Users/dhellmann/Envs/pymotw-ja/bin/../lib/python2.7/_weakrefset.py
Call to _remove on line 38 of /Users/dhellmann/Envs/pymotw-ja/bin/../lib/python2.7/_weakrefset.py

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 a tuple containing the type of exception, the exception object, and a traceback object.

 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
Exception TypeError: "argument of type 'NoneType' is not iterable" in <function _remove at 0x1004469b0> ignored
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.
trace
The trace module implements several code analysis features.
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.

Navigation

Bookmark and Share