trace – Follow Python statements as they are executed¶

Purpose:	Monitor which statements and functions are executed as a program runs to produce coverage and call-graph information.
Available In:	2.3 and later

The trace module helps you understand the way your program runs. You can trace the statements executed, produce coverage reports, and investigate the relationships between functions that call each other.

Command Line Interface¶

It is easy use trace directly from the command line. Given the following Python scripts as input:

from recurse import recurse

def main():
    print 'This is the main program.'
    recurse(2)
    return

if __name__ == '__main__':
    main()

def recurse(level):
    print 'recurse(%s)' % level
    if level:
        recurse(level-1)
    return

def not_called():
    print 'This function is never called.'

Tracing Execution¶

We can see which statements are being executed as the program runs using the --trace option.

$ python -m trace --trace trace_example/main.py

 --- modulename: main, funcname: <module>
main.py(7): """
main.py(12): from recurse import recurse
 --- modulename: recurse, funcname: <module>
recurse.py(7): """
recurse.py(12): def recurse(level):
recurse.py(18): def not_called():
main.py(14): def main():
main.py(19): if __name__ == '__main__':
main.py(20):     main()
 --- modulename: main, funcname: main
main.py(15):     print 'This is the main program.'
This is the main program.
main.py(16):     recurse(2)
 --- modulename: recurse, funcname: recurse
recurse.py(13):     print 'recurse(%s)' % level
recurse(2)
recurse.py(14):     if level:
recurse.py(15):         recurse(level-1)
 --- modulename: recurse, funcname: recurse
recurse.py(13):     print 'recurse(%s)' % level
recurse(1)
recurse.py(14):     if level:
recurse.py(15):         recurse(level-1)
 --- modulename: recurse, funcname: recurse
recurse.py(13):     print 'recurse(%s)' % level
recurse(0)
recurse.py(14):     if level:
recurse.py(16):     return
recurse.py(16):     return
recurse.py(16):     return
main.py(17):     return
 --- modulename: trace, funcname: _unsettrace
trace.py(80):         sys.settrace(None)

The first part of the output shows some setup operations performed by trace. The rest of the output shows the entry into each function, including the module where the function is located, and then the lines of the source file as they are executed. You can see that recurse() is entered three times, as you would expect from the way it is called in main().

Code Coverage¶

Running trace from the command line with the --count option will produce code coverage report information, so you can see which lines are run and which are skipped. Since your program is usually made up of multiple files, a separate coverage report is produced for each. By default the coverage report files are written to the same directory as the module, named after the module but with a .cover extension instead of .py.

$ python -m trace --count trace_example/main.py

This is the main program.
recurse(2)
recurse(1)
recurse(0)

And two output files, trace_example/main.cover:

       
from recurse import recurse
       
def main():
    print 'This is the main program.'
    recurse(2)
    return
       
if __name__ == '__main__':
    main()

and trace_example/recurse.cover:

       
def recurse(level):
    print 'recurse(%s)' % level
    if level:
        recurse(level-1)
    return
       
def not_called():
           print 'This function is never called.'

Note

Although the line def recurse(level): has a count of 1, that does not mean the function was only run once. It means the function definition was only executed once.

It is also possible to run the program several times, perhaps with different options, to save the coverage data and produce a combined report.

$ python -m trace --coverdir coverdir1 --count --file coverdir1/coverage\
_report.dat trace_example/main.py

Skipping counts file 'coverdir1/coverage_report.dat': [Errno 2] No such file or directory: 'coverdir1/coverage_report.dat'
This is the main program.
recurse(2)
recurse(1)
recurse(0)

$ python -m trace --coverdir coverdir1 --count --file coverdir1/coverage\
_report.dat trace_example/main.py

This is the main program.
recurse(2)
recurse(1)
recurse(0)

$ python -m trace --coverdir coverdir1 --count --file coverdir1/coverage\
_report.dat trace_example/main.py

This is the main program.
recurse(2)
recurse(1)
recurse(0)

Once the coverage information is recorded to the .cover files, you can produce reports with the --report option.

$ python -m trace --coverdir coverdir1 --report --summary --missing --fi\
le coverdir1/coverage_report.dat trace_example/main.py

lines   cov%   module   (path)
  515     0%   trace   (/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/trace.py)
    8   100%   trace_example.main   (trace_example/main.py)
    8    87%   trace_example.recurse   (trace_example/recurse.py)

Since the program ran three times, the coverage report shows values three times higher than the first report. The --summary option adds the percent covered information to the output above. The recurse module is only 87% covered. A quick look at the cover file for recurse shows that the body of not_called() is indeed never run, indicated by the >>>>>> prefix.

       
def recurse(level):
    print 'recurse(%s)' % level
    if level:
        recurse(level-1)
    return
       
def not_called():
>>>>>>     print 'This function is never called.'

Calling Relationships¶

In addition to coverage information, trace will collect and report on the relationships between functions that call each other.

For a simple list of the functions called, use --listfuncs:

$ python -m trace --listfuncs trace_example/main.py

This is the main program.
recurse(2)
recurse(1)
recurse(0)

functions called:
filename: /Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/trace.py, modulename: trace, funcname: _unsettrace
filename: trace_example/main.py, modulename: main, funcname: <module>
filename: trace_example/main.py, modulename: main, funcname: main
filename: trace_example/recurse.py, modulename: recurse, funcname: <module>
filename: trace_example/recurse.py, modulename: recurse, funcname: recurse

For more details about who is doing the calling, use --trackcalls.

$ python -m trace --listfuncs --trackcalls trace_example/main.py

This is the main program.
recurse(2)
recurse(1)
recurse(0)

calling relationships:

*** /Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/trace.py ***
    trace.Trace.runctx -> trace._unsettrace
  --> trace_example/main.py
    trace.Trace.runctx -> main.<module>

*** trace_example/main.py ***
    main.<module> -> main.main
  --> trace_example/recurse.py
    main.<module> -> recurse.<module>
    main.main -> recurse.recurse

*** trace_example/recurse.py ***
    recurse.recurse -> recurse.recurse

Programming Interface¶

For a little more control over the trace interface, you can invoke it from within your program using a Trace object. Trace lets you set up fixtures and other dependencies before running a single function or execing a Python command to be traced.

import trace
from trace_example.recurse import recurse

tracer = trace.Trace(count=False, trace=True)
tracer.run('recurse(2)')

Since the example only traces into the recurse() function, no information from main.py is included in the output.

$ python trace_run.py

 --- modulename: trace_run, funcname: <module>
<string>(1):   --- modulename: recurse, funcname: recurse
recurse.py(13):     print 'recurse(%s)' % level
recurse(2)
recurse.py(14):     if level:
recurse.py(15):         recurse(level-1)
 --- modulename: recurse, funcname: recurse
recurse.py(13):     print 'recurse(%s)' % level
recurse(1)
recurse.py(14):     if level:
recurse.py(15):         recurse(level-1)
 --- modulename: recurse, funcname: recurse
recurse.py(13):     print 'recurse(%s)' % level
recurse(0)
recurse.py(14):     if level:
recurse.py(16):     return
recurse.py(16):     return
recurse.py(16):     return

That same output could have been produced with the runfunc() method, too. runfunc() accepts arbitrary positional and keyword arguments, which are passed to the function when it is called by the tracer.

import trace
from trace_example.recurse import recurse

tracer = trace.Trace(count=False, trace=True)
tracer.runfunc(recurse, 2)

$ python trace_runfunc.py

 --- modulename: recurse, funcname: recurse
recurse.py(13):     print 'recurse(%s)' % level
recurse(2)
recurse.py(14):     if level:
recurse.py(15):         recurse(level-1)
 --- modulename: recurse, funcname: recurse
recurse.py(13):     print 'recurse(%s)' % level
recurse(1)
recurse.py(14):     if level:
recurse.py(15):         recurse(level-1)
 --- modulename: recurse, funcname: recurse
recurse.py(13):     print 'recurse(%s)' % level
recurse(0)
recurse.py(14):     if level:
recurse.py(16):     return
recurse.py(16):     return
recurse.py(16):     return

Saving Result Data¶

Counts and coverage information can be recorded as well, just as with the command line interface. The data must be saved explicitly, using the CoverageResults instance from the Trace object.

import trace
from trace_example.recurse import recurse

tracer = trace.Trace(count=True, trace=False)
tracer.runfunc(recurse, 2)

results = tracer.results()
results.write_results(coverdir='coverdir2')

$ python trace_CoverageResults.py

recurse(2)
recurse(1)
recurse(0)

$ find coverdir2

coverdir2
coverdir2/trace_example.recurse.cover

And the contents of coverdir2/trace_example.recurse.cover:

       #!/usr/bin/env python
       # encoding: utf-8
       #
       # Copyright (c) 2008 Doug Hellmann All rights reserved.
       #
       """
>>>>>> """
       
       #__version__ = "$Id$"
       #end_pymotw_header
       
>>>>>> def recurse(level):
    3:     print 'recurse(%s)' % level
    3:     if level:
    2:         recurse(level-1)
    3:     return
       
>>>>>> def not_called():
>>>>>>     print 'This function is never called.'

To save the counts data for generating reports, use the infile and outfile argument to Trace.

import trace
from trace_example.recurse import recurse

tracer = trace.Trace(count=True, trace=False, outfile='trace_report.dat')
tracer.runfunc(recurse, 2)

report_tracer = trace.Trace(count=False, trace=False, infile='trace_report.dat')
results = tracer.results()
results.write_results(summary=True, coverdir='/tmp')

Pass a filename to infile to read previously stored data, and a filename to outfile to write new results after tracing. If infile and outfile are the same, it has the effect of updating the file with cummulative data.

$ python trace_report.py

recurse(2)
recurse(1)
recurse(0)
lines   cov%   module   (path)
    8    50%   trace_example.recurse   (/Users/dhellmann/Documents/PyMOTW/src/PyMOTW/trace/trace_example/recurse.py)

Trace Options¶

The constructor for Trace takes several optional parameters to control runtime behavior.

count: Boolean. Turns on line number counting. Defaults to True.
countfuncs: Boolean. Turns on list of functions called during the run. Defaults to False.
countcallers: Boolean. Turns on tracking for callers and callees. Defaults to False.
ignoremods: Sequence. List of modules or packages to ignore when tracking coverage. Defaults to an empty tuple.
ignoredirs: Sequence. List of directories containing modules or packages to be ignored. Defaults to an empty tuple.
infile: Name of the file containing cached count values. Defaults to None.
outfile: Name of the file to use for storing cached count files. Defaults to None, and data is not stored.

PyMOTW

Page Contents

Navigation

This Page

Examples

trace – Follow Python statements as they are executed¶

Command Line Interface¶

Tracing Execution¶

Code Coverage¶

Calling Relationships¶

Programming Interface¶

Saving Result Data¶

Trace Options¶