Using Python's trace module to understand the flow of programs (from many angles)

By Vasudev Ram

Some time back, I had written this post:

Python's trace module and chained decorators

in which I had briefly described use of the Python standard library's trace module to help us understand and debug Python programs. In that post I showed a small program with 3 chained decorators. The trace module was used to trace the execution of the decorators and the functions that they decorated.

The trace output in that post also showed the difference between function definition and function execution, both of which occur at run time in Python, since it is a dynamic language.

In this post, I'm going to use the trace module in a few other ways.

Here is a small program in which we will use the trace module.

(Note that I said "in which", not "on which", because I am going to invoke the trace module as a library from within this program, and tell it to start tracing from a specific function call, unlike in my previous post (linked above), in which I used the trace module as though it was a program itself, by using the "python -m" option, to trace my own program containing those decorators.)

# This is a program to show some basic usage of the trace module 
# from the Python standard library.
# Author: Vasudev Ram - 
# http://jugad2.blogspot.in/p/about-vasudev-ram.html
# Copyright 2016 Vasudev Ram

def fa():
    fb()

def fb():
    fc()

def fc():
    fd(5)

def fd(n):
    if n <= 1:
        return
    else:
        fd(n - 1)

import trace

tracer = trace.Trace(
    count=0, trace=0, countfuncs=0, countcallers=1, 
)

tracer.run('fa()')
r = tracer.results()
r.write_results(show_missing=True, coverdir=".")

In this program, I have a function fa calling fb which calls fc which calls fd. Function fd also calls itself recursively, with a termination condition so the recursion is not infinite.

Note that the program contains all the three main programming constructs: sequential execution of statements, conditional execution and iteration (via the recursive call in function fd).

From the Python documentation, the trace.Trace() constructor has the following (partial) signature:

class trace.Trace(count=1, trace=1, countfuncs=0, countcallers=0, ...)

where I have used ellipsis (...) to represent the remaining arguments, which I do not pass. (See the docs (linked above, near top of post) for the full signature and the meaning of all the arguments. The ones I use are explained below.)

As for what those arguments do, again, from the docs:

Create an object to trace execution of a single statement or expression. All parameters are optional. count enables counting of line numbers. trace enables line execution tracing. countfuncs enables listing of the functions called during the run. countcallers enables call relationship tracking.

I ran the program simple_prog.py 4 times. Each time I passed a different combination of argument values to trace.Trace() - with only one argument set to 1 each time, and all the others set to 0 in that run. And each time I redirected the resulting trace output to an output file, except for the first run, in which Python created the output in the file simple_prog.cover (since the program being traced is named simple_prog.py.

The lines below show the sets of arguments passed, and the corresponding output file names for the trace output. (I will show the contents of each output file later, below.)

arg set 1: count=1, trace=0, countfuncs=0, countcallers=0, output: simple_prog.cover

arg set 2: count=0, trace=1, countfuncs=0, countcallers=0, output: run_2.txt

arg set 3: count=0, trace=0, countfuncs=1, countcallers=0, output: run_3.txt

arg set 4: count=0, trace=0, countfuncs=0, countcallers=1, output: run_4.txt

Notice that in each of the arg sets, only one flag is set.

I ran the program this time with just:

python simple_prog.py

since the tracing is started from within the program, unlike in my previous post (linked above) in which I started the tracing like this:

python -m trace -t test_chained_decorators.py

Here is the output for the 1st run, simple_prog.cover:

# This is a program to show some basic usage of the trace module 
       # from the Python standard library.
       # Author: Vasudev Ram - 
       # http://jugad2.blogspot.in/p/about-vasudev-ram.html
       # Copyright 2016 Vasudev Ram
       
>>>>>> def fa():
    1:     fb()
       
>>>>>> def fb():
    1:     fc()
       
>>>>>> def fc():
    1:     fd(5)
       
>>>>>> def fd(n):
    5:     if n <= 1:
    1:         return
           else:
    4:         fd(n - 1)
       
>>>>>> import trace
       
>>>>>> tracer = trace.Trace(
>>>>>>     count=1, trace=0, countfuncs=0, countcallers=0, 
       )
       
>>>>>> tracer.run('fa()') # This line starts the tracing process.
>>>>>> r = tracer.results()
>>>>>> r.write_results(show_missing=True, coverdir=".")

You can see that the output includes the counts of the number of times lines of code are called. Notice that there are no line counts for the def lines, presumably because function definitions are only supposed to be done once (by definition, ha ha), so it would not make sense to show it, and might even be confusing.

Here is the output for the 2nd run, run_2.txt:

--- modulename: simple_prog, funcname: <module>
<string>(1):   --- modulename: simple_prog, funcname: fa
simple_prog.py(6):     fb()
 --- modulename: simple_prog, funcname: fb
simple_prog.py(9):     fc()
 --- modulename: simple_prog, funcname: fc
simple_prog.py(12):     fd(5)
 --- modulename: simple_prog, funcname: fd
simple_prog.py(15):     if n <= 1:
simple_prog.py(18):         fd(n - 1)
 --- modulename: simple_prog, funcname: fd
simple_prog.py(15):     if n <= 1:
simple_prog.py(18):         fd(n - 1)
 --- modulename: simple_prog, funcname: fd
simple_prog.py(15):     if n <= 1:
simple_prog.py(18):         fd(n - 1)
 --- modulename: simple_prog, funcname: fd
simple_prog.py(15):     if n <= 1:
simple_prog.py(18):         fd(n - 1)
 --- modulename: simple_prog, funcname: fd
simple_prog.py(15):     if n <= 1:
simple_prog.py(16):         return
 --- modulename: trace, funcname: _unsettrace
trace.py(80):         sys.settrace(None)

Since the trace flag is set, we get line execution tracing. And due to that, there are 5 entries for function fd, since there are 5 calls to it (of which 4 are recursive).

Here is the output for the 3rd run, run_3.txt:

functions called:
filename: <string>, modulename: <string>, funcname: <module>
filename: D:\Anaconda-2.1.0-64\lib\trace.py, modulename: trace, funcname: _unsettrace
filename: simple_prog.py, modulename: simple_prog, funcname: fa
filename: simple_prog.py, modulename: simple_prog, funcname: fb
filename: simple_prog.py, modulename: simple_prog, funcname: fc
filename: simple_prog.py, modulename: simple_prog, funcname: fd

Since the countfuncs flag is set, it shows the functions called during the run of the program.

Here is the output for the 4th run, run_4.txt:

calling relationships:

*** <string> ***
  --> simple_prog.py
    <string>.<module> -> simple_prog.fa

*** D:\Anaconda-2.1.0-64\lib\trace.py ***
  --> <string>
    trace.Trace.runctx -> <string>.<module>
    trace.Trace.runctx -> trace._unsettrace

*** simple_prog.py ***
    simple_prog.fa -> simple_prog.fb
    simple_prog.fb -> simple_prog.fc
    simple_prog.fc -> simple_prog.fd
    simple_prog.fd -> simple_prog.fd

Since the countcallers flag is set, it shows the function call tree during the run of the program, i.e. what function called what other function(s). The last line shows the recursive call to fd.

So we can see, overall, that those four flags to trace.Trace(), allowed us to get insight into the behaviour of the program, from various angles or perspectives. This makes the trace module a useful tool for debugging and for understanding code that we have to work on.

- Enjoy.

- Vasudev Ram - Online Python training and programming

Signup to hear about new products and services I create.

Posts about Python  Posts about xtopdf

My ActiveState recipes

Share |

Python's trace module and chained decorators

By Vasudev Ram

I saw this example of using chained decorators on StackOverflow some time ago.

The trace module from the Python standard library allows you "to trace program execution, generate annotated statement coverage listings, print caller/callee relationships and list functions executed during a program run. It can be used in another program or from the command line." - from the trace module page (italics mine).

I used the trace module to trace the execution of statements in the chained decorators example (I modified the StackOverflow example a bit to add a main() function):

# test_chained_decorator.py
# An example of chained decorators.
# From Stack Overflow question at:
# http://stackoverflow.com/questions/739654/understanding-python-decorators/1594484#1594484

def makebold(fn):
    def wrapped():
        return "<b>" + fn() + "</b>"
    return wrapped

def makeitalic(fn):
    def wrapped():
        return "<i>" + fn() + "</i>"
    return wrapped

@makebold
@makeitalic
def hello():
    return "hello world"

def main():
    print hello()
    
if __name__ == '__main__':
    main()

Running the program as follows, under control of the trace module:

python -m trace -t test_chained_decorators.py

gives this output:

--- modulename: test_chained_decorators, funcname: 
test_chained_decorators.py(6): def makebold(fn):
test_chained_decorators.py(11): def makeitalic(fn):
test_chained_decorators.py(16): @makebold
test_chained_decorators.py(17): @makeitalic
 --- modulename: test_chained_decorators, funcname: makeitalic
test_chained_decorators.py(12):     def wrapped():
test_chained_decorators.py(14):     return wrapped
 --- modulename: test_chained_decorators, funcname: makebold
test_chained_decorators.py(7):     def wrapped():
test_chained_decorators.py(9):     return wrapped
test_chained_decorators.py(21): def main():
test_chained_decorators.py(24): if __name__ == '__main__':
test_chained_decorators.py(25):     main()
 --- modulename: test_chained_decorators, funcname: main
test_chained_decorators.py(22):     print hello()
 --- modulename: test_chained_decorators, funcname: wrapped
test_chained_decorators.py(8):         return "<b>" + fn() + "</b>"
 --- modulename: test_chained_decorators, funcname: wrapped
test_chained_decorators.py(13):         return "<i>" + fn() + "</i>"
 --- modulename: test_chained_decorators, funcname: hello
test_chained_decorators.py(19):     return "hello world"
<b><i>hello world</i></b>
 --- modulename: trace, funcname: _unsettrace
trace.py(80):         sys.settrace(None)

An interesting detail: if you look carefully at the trace output, you'll see that def statements get printed, but the statements nested inside each def, do not get printed immediately after the def's are printed (though they occur immediately after the defs, in the text of the program); I guess this is due to the fact that when Python executes a program, def's get executed, but "executing a def" is not the same as calling the defined function; it means that the function definition is parsed/compiled and stored, for later execution whenever the function is called. You can see in the output that the statements inside each def are actually called only when the function is called from other code.

The trace module has other options apart from -t; see the Python documentation for it, linked above in this post.

Overall, the trace module can be helpful to understand and debug Python programs, your own or those of others.


- Vasudev Ram - Dancing Bison Enterprises

Contact me

Share |