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 |