Tracing Executions¶

In this chapter, we show how to observe program state during an execution – a prerequisite for logging and interactive debugging. Thanks to the power of Python, we can do this in a few lines of code.

Prerequisites

• You should have read the Introduction to Debugging.
• Knowing a bit of Python is helpful for understanding the code examples in the book.

Tracing Python Programs¶

How do debugging tools access the state of a program during execution? For interpreted languages such as Python, this is a simple task. If a language is interpreted, it is typically fairly easy to control execution and to inspect state – since this is what the interpreter is doing already anyway. Debuggers are then implemented on top of hooks that allow interrupting execution and accessing program state.

Python makes such a hook available in the function sys.settrace(). You invoke it with a tracing function that will be called at every line executed, as in

sys.settrace(traceit)

Such a tracing function is convenient, as it simply traces everything. In contrast to an interactive debugger, where you have to select which aspect of the execution you're interested in, you can just print out a long trace into an execution log, to examine it later.

This tracing function takes the format

Here, event is a string telling what has happened in the program – for instance,

• 'line' – a new line is executed
• 'call' – a function just has been called
• 'return' – a function returns

The frame argument holds the current execution frame – that is, the function and its local variables:

• frame.f_lineno – the current line
• frame.f_locals – the current variables (as a Python dictionary)
• frame.f_code – the current code (as a Code object), with attributes such as
  • frame.f_code.co_name – the name of the current function

We can thus get a trace of the program by simply printing out these values:

The return value of the trace function is the function to be executed at the next event – typically, this is the function itself:

Let us try this out on the remove_html_markup() function introduced in the Introduction to Debugging:

We define a variant remove_html_markup_traced() which turns on tracing, invokes remove_html_markup(), and turns tracing off again.

Here is what we get when we run remove_html_markup_traced():

• We first get a call event (showing the call of remove_html_markup())
• We then get various line events (for each line of remove_html_markup())
• In the end, we get a return event (showing the return from remove_html_markup())

During the execution, we also see all local variables. As remove_html_markup() is called at the very beginning, the parameter s holds the argument "xyz". As more local variables are being assigned, these show up in our dictionary of local variables.

We see how the variable c takes one character of the input string at a time; the out variable accumulates them. and the tag and quote flags stay unchanged throughout the execution.

An interesting aspect is that we can actually access all these local variables as regular Python objects. We can, for instance, separately access the value of c by looking up frame.f_locals['c']:

This allows us to specifically monitor individual variables:

This tracing capability is tremendously powerful – actually, it is one of the reasons this book uses Python all over the place. In most other languages, inspecting the program state during execution is much more complex than the handful of lines we have needed so far.

To learn more about sys.settrace(), spend a moment to look up its documentation in the Python reference.

Indeed, as listed in the documentation: if sys.settrace() returns None, then tracing stops for the current scope; tracing will resume when the current function returns. This can be helpful for momentarily disable (expensive) tracing.

A Tracer Class¶

Let us refine our tracing function a bit. First, it would be nice if one could actually customize tracing just as needed. To this end, we introduce a Tracer class that does all the formatting for us, and which can be subclassed to allow for different output formats.

The traceit() method in Tracer is the same as above, and again is set up via sys.settrace(). It uses a log() method after the Python print() function.

The typical usage of Tracer, however, is as follows:

with Tracer():
    # Code to be traced
    ...

# Code no longer traced
...

When the with statement is encountered, the __enter__() method is called, which starts tracing. When the with block ends, the __exit__() method is called, and tracing is turned off. We take special care that the internal __exit__() method is not part of the trace, and that any other tracing function that was active before is being restored.

We build Tracer on top of a class named StackInspector, whose our_frame() and is_internal_error() methods us with providing better diagnostics in case of error.

Here's how we use the Tracer class. You see that everything works as before, except that it is nicer to use:

Accessing Source Code¶

We can now go and extend the class with additional features. It would be nice if it could actually display the source code of the function being tracked, such that we know where we are. In Python, the function inspect.getsource() returns the source code of a function or module. Looking up

module = inspect.getmodule(frame.f_code)

gives us the current module, and

inspect.getsource(module)

gives us its source code. All we then have to do is to retrieve the current line.

To implement our extended traceit() method, we use a bit of a hack. The Python language requires us to define an entire class with all methods as a single, continuous unit; however, we would like to introduce one method after another. To avoid this problem, we use a special hack: Whenever we want to introduce a new method to some class C, we use the construct

class C(C):
    def new_method(self, args):
        pass

This seems to define C as a subclass of itself, which would make no sense – but actually, it introduces a new C class as a subclass of the old C class, and then shadowing the old C definition. What this gets us is a C class with new_method() as a method, which is just what we want. (C objects defined earlier will retain the earlier C definition, though, and thus must be rebuilt.)

Using this hack, we can now redefine the traceit() method. Our new tracer shows the current line as it is executed.

Tracing Calls and Returns¶

Next, we'd like to report calling and returning from functions. For the return event, arg holds the value being returned.

Tracing Variable Changes¶

Finally, we'd again like to report variables – but only those that have changed. To this end, we save a copy of the last reported variables in the class, reporting only the changed values.

Here's how this works: If variable a is set to 10 (and we didn't have it so far), it is marked as changed:

If another variable b is added, and only b is changed, then only b is marked as changed:

If both variables keep their values, nothing changes:

But if new variables come along, they are listed again.

The following expression creates a comma-separated list of variables and values:

We can now put all of this together in our tracing function, reporting any variable changes as we see them. Note how we exploit the fact that in a call, all variables have a "new" value; and when we return from a function, we explicitly delete the "last" variables.

Here's the resulting trace of remove_html_markup() for a more complex input. You can see that the tracing output allows us to see which lines are executed as well as the variables whose value changes.

As you see, even a simple function can create a long execution log. Hence, we will now explore how to focus tracing on particular events.

Conditional Tracing¶

A log such as the above can very quickly become very messy – notably if executions take a long time, or if data structures become very complex. If one of our local variables were a list with 1,000 entries for instance, and were changed with each line, we'd be printing out the entire list with 1,000 entries for each step.

We could still load the log into, say, a text editor or a database and then search for specific values, but this is still cumbersome – and expensive. A better alternative, however, is to have our tracer only log while specific conditions hold.

To this end, we introduce a class ConditionalTracer, which gets a conditional expression to be checked during executions. Only if this condition holds do we list the current status. With

with ConditionalTracer(condition='c == "z"'):
    remove_html_markup(...)

we would obtain only the lines executed while c gets a value of 'z', and with

with ConditionalTracer(condition='quote'):
    remove_html_markup(...)

we would obtain only the lines executed while quote is True. If we have multiple conditions, we can combine them into one using and, or, or not.

Our ConditionalTracer class stores the condition in its condition attribute:

Its traceit() function evaluates condition and reports the current line only if it holds. To this end, it uses the Python eval() function which evaluates the condition in the context of the local variables of the program under test. If the condition gets set, we print out three dots to indicate the elapsed time.

The do_report() function returns True if the status is to be reported:

We put everything together in our traceit() function:

Here's an example. We see that quote is set only while the three characters b, a, and r are processed (as should be).

Here's the answer, illustrated in two examples. For syntax errors, we indeed get an exception:

If a variable is undefined, though, the condition evaluates to False:

We can also have the log focus on particular code locations only. To this end, we add the pseudo-variables function and line to our evaluation context, which can be used within our condition to refer to the current function name or line. Then, we invoke the original eval_cond() as above.

Again, here is an example. We focus on the parts of the function where the out variable is being set:

Using line and function in conditions is equivalent to conventional breakpoints in interactive debuggers. We will encounter them again in the next chapter.

Watching Events¶

As an alternative to conditional logging, we may also be interested to exactly trace when a variable not only has a particular value, but also when it changes its value.

To this end, we set up an EventTracer class that watches when some event takes place. It takes a list of expressions ("events") and evaluates them for each line; if any event changes its value, we log the status.

With

with EventTracer(events=['tag', 'quote']):
    remove_html_markup(...)

for instance, we would get a listing of all lines where tag or quote change their value; and with

with EventTracer(events=['function']):
    remove_html_markup(...)

we would obtain a listing of all lines where the current function changes.

Our EventTracer class stores the list of events in its events attribute:

Its events_changed() function evaluates the individual events and checks if they change.

We hook this into do_report(), the method that determines whether a line should be shown.

This allows us to track, for instance, how quote and tag change their values over time.

Continuously monitoring variable values at execution time is equivalent to the concept of watchpoints in interactive debuggers.

With this, we have all we need for observing what happens during execution: We can explore the entire state, and we can evaluate conditions and events we are interested in. In the next chapter, we will see how to turn these capabilities into an interactive debugger, where we can query all these things interactively.

Efficient Tracing¶

While our framework is very flexible (and can still be extended further), it also is slow, since we have to evaluate all conditions and events for every single line of the program. Just how slow are things? We can easily measure this.

Here's the untraced execution time in seconds:

And here's the traced execution time:

We see that the traced execution time is several hundred times slower:

We can still speed up our implementation somewhat, but still will get nowhere near the untraced execution time.

There is a trick, though, that allows us to execute programs at full speed while being traced. Rather than dynamically checking at run time whether a condition is met, we can also statically inject appropriate code into the program under test. This way, the non-traced code is executed at normal speed.

There is a downside, though: This only works if the condition to be checked is limited to specific locations – because it is precisely these locations where we insert our tracing code. With this limitation, though, static tracing can speed up things significantly.

How does static code injection work? The trick involves rewriting the program code to insert special debugging statements at the given locations. This way, we do not need to use the tracing function at all.

The following insert_tracer() function demonstrates this. It takes a function as well as a list of breakpoint lines where to insert tracing statements. At each given line, it injects the code

into the function definition, which calls into this tracer:

insert_tracer() then compiles the resulting code into a new "traced" function, which it then returns.

Here's an example: inserting two breakpoints in (relative) Lines 7 and 18 of remove_html_markup() results in the following (rewritten) definition of remove_html_markup_traced():

If we execute the statically instrumented remove_html_markup_traced(), we obtain the same output as when using a dynamic tracer. Note that the source code listed shows the original code; the injected calls into TRACER do not show up.

How fast is the static tracer compared with the dynamic tracer? This is the execution time of the above code:

Compare this with the equivalent dynamic tracer:

We see that the static tracker is several times faster – an advantage that will only increase further as more non-traced code is executed. If our code looks like this:

and we then execute it with

we will spend quite some time.

Indeed: Stepping line by line through some function can be pretty expensive, as every call, line, and return of some_extreme_function() and remove_html_markup() is tracked.

On the other hand, the static tracker is limited to conditions that refer to a specific location in the code. If we want to check whether some variable changes, for instance, we have to perform a (nontrivial) static analysis of the code to determine possible locations for a change. If a variable is changed indirectly through references or pointers (a common risk in system-level languages like C), there is no alternative to actually watching its value after each instruction.

Tracing Binary Executables¶

Debuggers that act on binary code (say, code compiled from C) operate similarly as our "static" tracer: They take a location in the binary code and replace its instruction with a break instruction that interrupts execution, returning control to the debugger. The debugger then replaces the break instruction with the original instruction before resuming execution.

If the code cannot be altered (for instance, because it is in read-only memory), however, then debuggers resort to the "dynamic" tracing method, executing one instruction at a time and checking the program counter for its current value after each step.

To provide a minimum of efficient support, some processor architectures, such as x86, provide hardware breakpoints. Programmers (or more precisely, debugging tools) can define a set of specific values for the program counter to watch, and if the program counter reaches one of these values, execution is interrupted to return to the debugger. Likewise, hardware watchpoints will check specific memory locations at run time for changes and given values. There are also hardware watchpoints that break when a specific memory location is read from. Both hardware watchpoints and hardware breakpoints allow a limited tracking of stopping conditions while still maintaining original execution speed – and the best debugging tools will use a mix of static tracing, dynamic tracing, and hardware tracing.

Lessons Learned¶

• Interpreted languages can provide debugging hooks that allow controlling program execution and access program state.
• Tracing can be limited to specific conditions and events:
  • A breakpoint is a condition referring to a particular location in the code.
  • A watchpoint is an event referring to a particular state change.
• Compiled languages allow instrumenting code at compile time, injecting code that allows handing over control to a tracing or debugging tool.

Next Steps¶

In the next chapter, we will see how to

• leverage our tracing infrastructure for interactive debugging

Background¶

Debugging interfaces like Python sys.settrace() are common in all programming languages that provide support for interactive debugging, providing support for executing programs step by step and inspecting program state along the way.

Low-Level Debugging Interfaces¶

The first set of interfaces considered takes place at a low level, allowing access to machine level features. On Linux and other UNIX-like systems, the ptrace() system call provides a means by which one process (the 'tracer') may observe and control the execution of another process (the 'tracee'), and examine and change the tracee's memory and registers.

ptrace() is a low-level interface, which allows stepping over individual machine instructions and to read raw memory. In order to map instructions back to original statements and translate memory contents to variable values, compilers can include debugging information in the produced binaries, which debuggers then read out during a debugging session.

High-Level Debugging Interfaces¶

The second set of interfaces allows accessing the program's internals using the concepts of the program – i.e. variables and code locations, as Python does. The Java Debug Interface (JDI) is a high-level interface for implementing a debugger (or tracer) on top of Java. This introduction to JDI shows how to build a debugger using this interface in a few steps.

For JavaScript, Mozilla's Debugger API and Google's chrome.debugger API similarly allow tracing and inspecting program execution.

Exercises¶

Exercise 1: Exception Handling¶

So far, we have only seen execution of lines in individual functions. But if a function raises an exception, we also may want to catch and report this. Right now, an exception is being raised right through our tracer, interrupting the trace.

Extend the Tracer class (or the EventTracer subclasses) such that exceptions (event type 'exception') are properly traced, too, say as

fail() raises ZeroDivisionError: division by zero

See the Python documentation for sys.settrace().

Exercise 2: Syntax-Based Instrumentation¶

Adding instrumentation to source code is a complicated business, notably because it is not always easy to determine where and how to instrument. If a Python line starts with

if condition:

where should one insert code to instrument it?

A much more elegant way to instrument code is to add instrumentation after the code has already been parsed. Python code, like most other code, is first parsed into an intermediate tree-like structure (called an abstract syntax tree, or AST). This AST can then be inspected and manipulated, before a second step compiles it into low-level instruction sequences to be executed.

Let us start with an example. Here is an AST resulting from parsing a very simple piece of code:

You see that the function foo() has a FunctionDef node with four children: The function name ("foo"), its arguments (arguments; currently empty), followed by the statements that make the function body – Assign for the assignment, Return for the return statement.

We obtain and manipulate the AST through the Python ast module. The official Python ast reference is complete, but a bit brief; the documentation "Green Tree Snakes - the missing Python AST docs" provides an excellent introduction.

To instrument the above code, we need to insert a new statement as a child to FunctionDef node.

Here's the code we want to inject:

The root of an ast.parse() tree actually is a Module node; we go directly to its child, which is the Expr node we want to inject.

To inject the code, we use the NodeTransformer class as described in the Python ast documentation. We vist all function definitions (FunctionDef) and replace them with a new function definition in which the body gets an additional child – namely our subtree to be injected.

This is what our new tree looks like:

This is what the tree looks like when converted back to source code:

We can now compile the new source into a function:

... and happily invoke our instrumented function.

Your task is to implement a function insert_tracer_ast(function, breakpoints) that works like insert_tracer(), above, except that it uses this AST-based mechanism to inject debugging code into the given function.