Tracing a Program As It Runs¶

There are two ways to inject code to watch a program run: tracing and profiling. They are similar, but intended for different purposes and so have different constraints. The easiest, but least efficient, way to monitor a program is through a trace hook, which can be used to write a debugger, monitor code coverage, or achieve many other purposes.

The trace hook is modified by passing a callback function to sys.settrace() . The callback will receive three arguments: the stack frame from the code being run, a string naming the type of notification, and an event-specific argument value. the table below lists the seven event types for different levels of information that occur as a program is being executed.

Event Hooks for settrace() ¶ Event When it occurs Argument value call Before a line is executed None line Before a line is executed None return Before a function returns The value being returned exception After an exception occurs The (exception, value, traceback) tuple c_call Before a C function is called The C function object c_return After a C function returns None c_exception After a C function throws an error None

Tracing Function Calls¶ A call event is generated before every function call. The frame passed to the callback can be used to find out which function is being called and from where. sys_settrace_call.py ¶ 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 #!/usr/bin/env python3 # encoding: utf-8 import sys def trace_calls ( frame , event , arg ): if event != 'call' : return co = frame . f_code func_name = co . co_name if func_name == 'write' : # Ignore write() calls from printing return func_line_no = frame . f_lineno func_filename = co . co_filename if not func_filename . endswith ( 'sys_settrace_call.py' ): # Ignore calls not in this module return caller = frame . f_back caller_line_no = caller . f_lineno caller_filename = caller . f_code . co_filename print ( '* Call to' , func_name ) print ( '* on line {} of {} ' . format ( func_line_no , func_filename )) print ( '* from line {} of {} ' . format ( caller_line_no , caller_filename )) return def b (): print ( 'inside b()

' ) def a (): print ( 'inside a()

' ) b () sys . settrace ( trace_calls ) a () This example ignores calls to write() , as used by print to write to sys.stdout . $ python3 sys_settrace_call.py * Call to a * on line 35 of sys_settrace_call.py * from line 41 of sys_settrace_call.py inside a() * Call to b * on line 31 of sys_settrace_call.py * from line 37 of sys_settrace_call.py inside b()

Tracing Inside Functions¶ The trace hook can return a new hook to be used inside the new scope (the local trace function). It is possible, for instance, to control tracing to only run line-by-line within certain modules or functions. sys_settrace_line.py ¶ 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 #!/usr/bin/env python3 # encoding: utf-8 import functools import sys def trace_lines ( frame , event , arg ): if event != 'line' : return co = frame . f_code func_name = co . co_name line_no = frame . f_lineno print ( '* {} line {} ' . format ( func_name , line_no )) def trace_calls ( frame , event , arg , to_be_traced ): if event != 'call' : return co = frame . f_code func_name = co . co_name if func_name == 'write' : # Ignore write() calls from printing return line_no = frame . f_lineno filename = co . co_filename if not filename . endswith ( 'sys_settrace_line.py' ): # Ignore calls not in this module return print ( '* Call to {} on line {} of {} ' . format ( func_name , line_no , filename )) if func_name in to_be_traced : # Trace into this function return trace_lines return def c ( input ): print ( 'input =' , input ) print ( 'Leaving c()' ) def b ( arg ): val = arg * 5 c ( val ) print ( 'Leaving b()' ) def a (): b ( 2 ) print ( 'Leaving a()' ) tracer = functools . partial ( trace_calls , to_be_traced = [ 'b' ]) sys . settrace ( tracer ) a () In this example, the list of functions is kept in the variable :py``to_be_traced``, so when trace_calls() runs it can return trace_lines() to enable tracing inside of b() . $ python3 sys_settrace_line.py * Call to a on line 49 of sys_settrace_line.py * Call to b on line 43 of sys_settrace_line.py * b line 44 * b line 45 * Call to c on line 38 of sys_settrace_line.py input = 10 Leaving c() * b line 46 Leaving b() Leaving a()

Watching the Stack¶ Another useful way to use the hooks is to keep up with which functions are being called, and what their return values are. To monitor return values, watch for the return event. sys_settrace_return.py ¶ 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 #!/usr/bin/env python3 # encoding: utf-8 import sys def trace_calls_and_returns ( frame , event , arg ): co = frame . f_code func_name = co . co_name if func_name == 'write' : # Ignore write() calls from printing return line_no = frame . f_lineno filename = co . co_filename if not filename . endswith ( 'sys_settrace_return.py' ): # Ignore calls not in this module return if event == 'call' : print ( '* Call to {} on line {} of {} ' . format ( func_name , line_no , filename )) return trace_calls_and_returns elif event == 'return' : print ( '* {} => {} ' . format ( func_name , arg )) return def b (): print ( 'inside b()' ) return 'response_from_b ' def a (): print ( 'inside a()' ) val = b () return val * 2 sys . settrace ( trace_calls_and_returns ) a () The local trace function is used for watching return events, so trace_calls_and_returns() needs to return a reference to itself when a function is called, so the return value can be monitored. $ python3 sys_settrace_return.py * Call to a on line 32 of sys_settrace_return.py inside a() * Call to b on line 27 of sys_settrace_return.py inside b() * b => response_from_b * a => response_from_b response_from_b