Easy tracing of nested function calls in Python

August 22nd, 2012 at 4:24 am

Sometimes, when executing algorithms with complex function call sequences, and especially ones that require recursion, it’s useful to see what calls actually occurred during execution, their arguments and return values, and so on.

Here is a simple Python decorator (works on both 2.7 and 3.2+) that helps me do it without much effort for new code:

import sys
from functools import wraps

class TraceCalls(object):
    """ Use as a decorator on functions that should be traced. Several
        functions can be decorated - they will all be indented according
        to their call depth.
    """
    def __init__(self, stream=sys.stdout, indent_step=2, show_ret=False):
        self.stream = stream
        self.indent_step = indent_step
        self.show_ret = show_ret

        # This is a class attribute since we want to share the indentation
        # level between different traced functions, in case they call
        # each other.
        TraceCalls.cur_indent = 0

    def __call__(self, fn):
        @wraps(fn)
        def wrapper(*args, **kwargs):
            indent = ' ' * TraceCalls.cur_indent
            argstr = ', '.join(
                [repr(a) for a in args] +
                ["%s=%s" % (a, repr(b)) for a, b in kwargs.items()])
            self.stream.write('%s%s(%s)\n' % (indent, fn.__name__, argstr))

            TraceCalls.cur_indent += self.indent_step
            ret = fn(*args, **kwargs)
            TraceCalls.cur_indent -= self.indent_step

            if self.show_ret:
                self.stream.write('%s--> %s\n' % (indent, ret))
            return ret
        return wrapper

And here’s how we can use it:

@TraceCalls()
def iseven(n):
    return True if n == 0 else isodd(n - 1)

@TraceCalls()
def isodd(n):
    return False if n == 0 else iseven(n - 1)

print(iseven(7))

Output:

iseven(7)
  isodd(6)
    iseven(5)
      isodd(4)
        iseven(3)
          isodd(2)
            iseven(1)
              isodd(0)
False

The indentation level is shared between different functions – this is a key feature of the tracer. Note that the tracer is a class; while a function can also serve as a decorator, I find a class easier to reason about. Moreover, this tracer has some useful parameters to tweak and a decorator with arguments is much simpler to express with a class. Here are the parameters:

  • stream: the stream to print tracing output to. By default it’s printed to sys.stdout.
  • indent_step: by how many space chars to grow the indentation for each nested call.
  • show_ret: when True, shows the return value of each call.

What follows is an example that demonstrates a less linear call sequence and also the usage of some of the parameters:

@TraceCalls(indent_step=4, show_ret=True)
def flatten(lst):
    if isinstance(lst, list):
        return sum((flatten(item) for item in lst), [])
    else:
        return [lst]

list(flatten([1, 2, [3, [4, 5], 6, [7, [9], 12]], 4, [6, 9]]))

Output:

flatten([1, 2, [3, [4, 5], 6, [7, [9], 12]], 4, [6, 9]])
    flatten(1)
    --> [1]
    flatten(2)
    --> [2]
    flatten([3, [4, 5], 6, [7, [9], 12]])
        flatten(3)
        --> [3]
        flatten([4, 5])
            flatten(4)
            --> [4]
            flatten(5)
            --> [5]
        --> [4, 5]
        flatten(6)
        --> [6]
        flatten([7, [9], 12])
            flatten(7)
            --> [7]
            flatten([9])
                flatten(9)
                --> [9]
            --> [9]
            flatten(12)
            --> [12]
        --> [7, 9, 12]
    --> [3, 4, 5, 6, 7, 9, 12]
    flatten(4)
    --> [4]
    flatten([6, 9])
        flatten(6)
        --> [6]
        flatten(9)
        --> [9]
    --> [6, 9]
--> [1, 2, 3, 4, 5, 6, 7, 9, 12, 4, 6, 9]

References:

Related posts:

  1. Finding out where a function was called from
  2. SICP sections 3.5.4 – 3.5.5
  3. SICP sections 4.4.2 – 4.4.4
  4. Weighted random generation in Python
  5. Construction of function static variables in C++ is not thread safe

8 Responses to “Easy tracing of nested function calls in Python”

  1. Joel NothmanNo Gravatar Says:

    Perhaps it’s not a great idea to reset TraceCalls.cur_indent to 0 each time a TraceCalls is instantiated. The proposed will break if @TraceCalls() is used on a function defined within another function call.

    But really, the idea of nested traces only makes sense if multiple functions share the same stream and indent size, so the following application makes more sense:

    trace_calls = TraceCalls()

    @trace_calls
    def is_odd(…): …

    @trace_calls
    def is_odd(…): …

    Since show_ret may be set differently for each wrapped function, you could offer the syntax:

    @trace_calls.show_return

    by modifying TraceCalls.__call__ to take a default show_ret=False argument, and defining TraceCalls.show_return as partial(__call__, show_ret=True)

  2. A N OwenNo Gravatar Says:

    Typo, need comma after ’4′:

    @TraceCalls(indent_step=4, show_ret=True)
    def flatten(lst):
    … etc …

  3. elibenNo Gravatar Says:

    A N Owen,

    Thanks, fixed.

  4. Adam MatanNo Gravatar Says:

    Great tool! Thanks for publishing. Got me reading the documentation for functools.wraps.

  5. TimNo Gravatar Says:

    Nice article!

    Very useful. Already using it.

    Thanks!

  6. Calvin Spealman (@ironfroggy)No Gravatar Says:

    Excellent tutorial. I think there is a lack of good understanding about how to write tracers, and those of us with the need for them all fumble a bit to learn the details. They aren’t as friendly as they could be, but abstractions like this make them a lot nicer.

    I’ve been working on my own abstraction around the tracer system, called tracerlib.

    http://tracerlib.readthedocs.org/en/latest/index.html

  7. AniliusNo Gravatar Says:

    I’m looking for one that has no errors this one seems to have a indentation error on line 47

  8. Assaf LavieNo Gravatar Says:

    You rock, Eli!
    Found this by googling for “python trace function arguments” and it totally uncovered my recursion bug.. :)

Leave a Reply

To post code with preserved formatting, enclose it in `backticks` (even multiple lines)