How can I track the values of a local variable in Python?

Question

My algorithm loops over seconds of data. For each second-worth-of-data, I return a value, that is the result of a fairly involved computation involving multiple submodules and subclasses. Some of these classes are re-initialized each second.

For debugging purposes, a few times I have been in the situation that I have wanted to plot the value of a certain local variable in one of these classes over time. Something external would have to serialize and log the values, because the class exists for only a second. It has been a different local variable each time.

How can I do achieve my aim properly in terms of software design, without it taking me hours every time and without writing more than a line or two of new code each time I want to do this?

Ideally, one solution I have considered would be to have something like a global IO stream, or something like that, that I would "just be around" without having to initialize each class with it, so I could just insert some sort of MySerializer << [mylocalvariable, timestamp] command at any point in the code, and then when the run finished I could check if MySerializer is empty and if not I could plot what what is in it... or something like that. Better still if I could do this for multiple local variables in different classes. Would this solution be good? How could I do this?

Or to be able to do this in an aspect-oriented way, with some outside object "looking at the code" without changing it, building a buffer of values of that local variable, and spitting them out to a plot in the end. How might I do this?

Is there a better solution that either of these? Which design patterns suit this situation?

What I have done is in the past is to return that local variable to whoever holds the function, who then in turn has to return that value it has received, and so on and so forth, all the way up to the top. This is a huge mess and has to be written and deleted each time.

Answer 1

I had in mind something really simple like this:

#the decorator
def debug_function(func):
    def wrapper(*args, **kwargs):
        res = func(*args, **kwargs)
        print('debug:', res)
        return res

    return wrapper


#proof of concept:
@debug_function
def square(number):
    return number*number

class ClassA:
    def __init__(self):
        self.Number = 42

    @debug_function
    def return_number(self):
        return self.Number


if __name__ == '__main__':
    result = [square(i) for i in range(5)]
    print(result)

    my_obj = ClassA()
    n = my_obj.return_number()
    print(n)

In short, write a simple decorator that logs the result of your function somewhere (above I only write it out to the terminal, but this could be extended to use a log file or similar). Then you decorate whatever function you want to track and will get its return value whenever the function is called. In the code above I show what it does for a simple function and a class method. The result of the example code looks like this:

debug: 0
debug: 1
debug: 4
debug: 9
debug: 16
[0, 1, 4, 9, 16]
debug: 42
42

EDIT 2:

I edited the code below to use the actual function instead of just its __name__ to store the intermediate values. This should make it somewhat less error prone.

EDIT:

For storing values in memory, I would again go as simple as possible and just store the values in a list. For the simple example outlined above, possibly a global list object would be enough. However, as you most likely want to look at more than one function at a time, I'd rather suggest to design the decorator as a class and store one list per function in a class attribute. More about this in the example code.

The real problem is the storing of local variables. In order to do this you have to change the actual code of your function. Naturally, you don't want to do this 'by hand', but want your decorator to take care of this. Here it becomes tricky. After looking around for a while, I found a package called bytecode (which works at least for Python 3.6). There are most likely other options, but I decided to go with this one. bytecode allows you to translate the python bytecode into human-readable form, modify it, and translate it back to python bytecode. I have to admit that I'm a bit out of my depth here, but what I did was to write a few small functions, look at the translated code and design a piece of code that does what I want.

So, in this example the objective is to decorate the function to be tested, such that the decorator takes a list of strings as argument, where each string is the name of a variable that should be tracked. It then adds code to the function body that packs the final values of all listed variables in a tuple and returns the tuple together with the real return value. The 'wrapper' function then collects the tracked values and appends them to a function-specific list of values which can be read at any point in the code.

So here it goes. Put the actual decorator in its own file, I call it here debug_function.py:

from bytecode import Bytecode, Instr

class debug_function(object):
    """
    Decorator that takes a list of variable names as argument. Everytime
    the decorated function is called, the final states of the listed
    variables are logged and can be read any time during code execution.
    """
    _functions = {}
    def __init__(self, varnames):
        self.varnames = varnames


    def __call__(self, func):
        print('logging variables {} of function {}'.format(
            ','.join(self.varnames), func.__name__
        ))
        debug_function._functions[func] = []
        c = Bytecode.from_code(func.__code__)
        extra_code = [
            Instr('STORE_FAST', '_res')
        ]+[
            Instr('LOAD_FAST', name) for name in self.varnames
        ]+[
            Instr('BUILD_TUPLE', len(self.varnames)),
            Instr('STORE_FAST', '_debug_tuple'),
            Instr('LOAD_FAST', '_res'),
            Instr('LOAD_FAST', '_debug_tuple'),
            Instr('BUILD_TUPLE', 2),
            Instr('STORE_FAST', '_result_tuple'),
            Instr('LOAD_FAST', '_result_tuple'),
        ]
        c[-1:-1]= extra_code
        func.__code__=c.to_code()

        def wrapper(*args, **kwargs):
            res, values = func(*args, **kwargs)
            debug_function._functions[func].append(values)
            return res

        return wrapper

    @staticmethod
    def get_values(func):
        return debug_function._functions[func]

Then, let's generate again some functions to be checked, which we decorate with this decorator. Put these, for instance, in functions.py

from debug_function import debug_function

@debug_function(['c','d'])
def test_func(a,b):
    c = a+b
    d = a-b
    return c+d


class test_class:
    def __init__(self, value):
        self.val = value

    @debug_function(['y'])
    def test_method(self, *args):
        x = sum(args)
        y = 1
        for arg in args:
            y*=arg
        return x+y

Finally, call the functions and look at the output. debug_function has a static method called get(), which takes the function you want information on as argument and returns a list of tuples. Each of these tuples contains the final values of all the local variables you wanted to track after one call to that function. The values are in the same order in which they were listed in the decorator statement. With an 'inverse' zip, you can easily separate these tuples.

from debug_function import debug_function
from functions import test_func, test_class

results = [test_func(i,j) for i in range(5) for j in range(8,12)]
c,d = zip(*debug_function.get_values(test_func))
print('results:', results)
print('intermediate values:')
print('c =', c)
print('d =', d)

my_class = test_class(7)
results2 = [
    my_class.test_method(i,j,4,2) for i in range(5) for j in range(8,12)
]
y, = zip(*debug_function.get_values(test_class.test_method))
print('results:', results2)
print('intermediate values:')
print('y =', y)

The output of the calls looks like this:

logging variables c,d of function test_func
logging variables y of function test_method
results: [0, 0, 0, 0, 2, 2, 2, 2, 4, 4, 4, 4, 6, 6, 6, 6, 8, 8, 8, 8]
intermediate values:
c = (8, 9, 10, 11, 9, 10, 11, 12, 10, 11, 12, 13, 11, 12, 13, 14, 12, 13, 14, 15)
d = (-8, -9, -10, -11, -7, -8, -9, -10, -6, -7, -8, -9, -5, -6, -7, -8, -4, -5, -6, -7)
results: [14, 15, 16, 17, 79, 88, 97, 106, 144, 161, 178, 195, 209, 234, 259, 284, 274, 307, 340, 373]
intermediate values:
y = (0, 0, 0, 0, 64, 72, 80, 88, 128, 144, 160, 176, 192, 216, 240, 264, 256, 288, 320, 352)

I probably should explain a bit better how this works, please ask if anything stayed unclear. As said before, this decorator only stores the final value of each variable (i.e. the value that variable has after the function code has been executed). If you have a more complex function, you may be interested what the value is at, e.g., each variable assignment -- in this case you'll have to do a bit more work, but it should be doable.

Hope this helps