Wednesday, February 3, 2016

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.)

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.)

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.

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.