Doug Hellmann

PyMOTW: sys, Part 5: Tracing Your Program As It Runs

2009-11-08T10:47:00.001-05:00

Tracing Your Program As It Runs

There are two ways to inject code to watch your 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 your program is through a trace hook, which can be used for writing a debugger, code coverage monitoring, or many other purposes.

The trace hook is modified by passing a callback function to sys.settrace(). The callback is passed three arguments, frame (the stack frame from the code being run), event (a string naming the type of notification), and arg (an event-specific value). There are 7 event types for different levels of information that occur as your program is being executed.

Event	When	arg value
`'call'`	Before a function 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.

#!/usr/bin/env python
# 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 print statements
        return
    func_line_no = frame.f_lineno
    func_filename = co.co_filename
    caller = frame.f_back
    caller_line_no = caller.f_lineno
    caller_filename = caller.f_code.co_filename
    print 'Call to %s on line %s of %s from line %s of %s' % \
        (func_name, func_line_no, func_filename,
         caller_line_no, caller_filename)
    return

def b():
    print 'in b()'

def a():
    print 'in a()'
    b()

sys.settrace(trace_calls)
a()

This example ignores calls to write(), as used by print to write to sys.stdout.

$ python sys_settrace_call.py
Call to a on line 27 of sys_settrace_call.py from line 32 of sys_settrace_call.py
in a()
Call to b on line 24 of sys_settrace_call.py from line 29 of sys_settrace_call.py
in 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.

#!/usr/bin/env python
# encoding: utf-8

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
    filename = co.co_filename
    print '  %s line %s' % (func_name, line_no)

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 print statements
        return
    line_no = frame.f_lineno
    filename = co.co_filename
    print 'Call to %s on line %s of %s' % (func_name, line_no, filename)
    if func_name in TRACE_INTO:
        # 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()'
    
TRACE_INTO = ['b']

sys.settrace(trace_calls)
a()

Here the global list of functions is kept in the variable TRACE_INTO, so when trace_calls() runs it can return trace_lines() to enable tracing inside of b().

$ python sys_settrace_line.py
Call to a on line 40 of sys_settrace_line.py
Call to b on line 35 of sys_settrace_line.py
  b line 36
  b line 37
Call to c on line 31 of sys_settrace_line.py
input = 10
Leaving c()
  b line 38
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.

#!/usr/bin/env python
# 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 print statements
        return
    line_no = frame.f_lineno
    filename = co.co_filename
    if event == 'call':
        print 'Call to %s on line %s of %s' % (func_name, line_no, filename)
        return trace_calls_and_returns
    elif event == 'return':
        print '%s => %s' % (func_name, arg)
    return

def b():
    print 'in b()'
    return 'response_from_b '

def a():
    print 'in a()'
    val = b()
    return val * 2

sys.settrace(trace_calls_and_returns)
a()

The local trace function is used for watching returns, so we need to return trace_calls_and_returns when a function is called.

$ python sys_settrace_return.py
Call to a on line 25 of sys_settrace_return.py
in a()
Call to b on line 21 of sys_settrace_return.py
in b()
b => response_from_b
a => response_from_b response_from_b

Exception Propagation

Exceptions can be monitored by looking for the exception event in a local trace function. When an exception occurs, the trace hook is called with the (type, instance, traceback) triple passed as arg.

#!/usr/bin/env python
# encoding: utf-8

import sys

def trace_exceptions(frame, event, arg):
    if event != 'exception':
        return
    co = frame.f_code
    func_name = co.co_name
    line_no = frame.f_lineno
    filename = co.co_filename
    exc_type, exc_value, exc_traceback = arg
    print 'Tracing exception: %s "%s" on line %s of %s' % \
        (exc_type.__name__, exc_value, line_no, func_name)

def trace_calls(frame, event, arg):
    if event != 'call':
        return
    co = frame.f_code
    func_name = co.co_name
    if func_name in TRACE_INTO:
        return trace_exceptions

def c():
    raise RuntimeError('generating exception in c()')

def b():
    c()
    print 'Leaving b()'

def a():
    b()
    print 'Leaving a()'
    
TRACE_INTO = ['a', 'b', 'c']

sys.settrace(trace_calls)
try:
    a()
except Exception, e:
    print 'Exception handler:', e

Take care to limit where the local function is applied because some of the internals of
formatting error messages generate, and ignore, their own exceptions. Every exception is
seen by the trace hook, whether the caller catches and ignores it or not.

$ python sys_settrace_exception.py
Tracing exception: RuntimeError "generating exception in c()" on line 26 of c
Tracing exception: RuntimeError "generating exception in c()" on line 29 of b
Tracing exception: RuntimeError "generating exception in c()" on line 33 of a
Exception handler: generating exception in c()

See also

profile: The profile module documentation shows how to use a ready-made profiler.
Types and Members: The descriptions of frame and code objects and their attributes.
Tracing python code: Another settrace() tutorial.
Wicked hack: Python bytecode tracing: Ned Batchelder’s experiments with tracing with more granularity than source line level.

PyMOTW Home

The canonical version of this article

PyMOTW: sys, Part 4: Exception Handling

2009-11-01T15:14:00.001-05:00

Exception Handling

sys includes features for trapping and working with exceptions.

Unhandled Exceptions

Many applications are structured with a main loop that wraps execution in a global exception handler to trap errors not handled at a lower level. Another way to achieve the same thing is by setting the sys.excepthook to a function that takes three arguments (error type, error value, and traceback) and let it deal with unhandled errors.

import sys

def my_excepthook(type, value, traceback):
    print 'Unhandled error:', type, value

sys.excepthook = my_excepthook

print 'Before exception'

raise RuntimeError('This is the error message')

print 'After exception'

Since there is no try:except block around the line where the exception is raised the following print statement is not run, even though the except hook is set.

$ python sys_excepthook.py
Before exception
Unhandled error: <type 'exceptions.RuntimeError'> This is the error message

Current Exception

There are times when an explicit exception handler is preferred, either for code clarity or to avoid conflicts with libraries that try to install their own excepthook. In these cases you may want to write a common handler function, but avoid passing the exception object to it explicitly. You can get the current exception for a thread by calling exc_info().

The return value of exc_info() is a three member tuple containing the exception class, an exception instance, and a traceback. Using exc_info() is preferred over the old form (with exc_type, exc_value, and exc_traceback) because it is thread-safe.

import sys
import threading
import time

def do_something_with_exception():
    exc_type, exc_value = sys.exc_info()[:2]
    print 'Handling %s exception with message "%s" in %s' % \
        (exc_type.__name__, exc_value, threading.current_thread().name)

def cause_exception(delay):
    time.sleep(delay)
    raise RuntimeError('This is the error message')

def thread_target(delay):
    try:
        cause_exception(delay)
    except:
        do_something_with_exception()

threads = [ threading.Thread(target=thread_target, args=(0.3,)),
            threading.Thread(target=thread_target, args=(0.1,)),
            ]
for t in threads:
    t.start()
for t in threads:
    t.join()

Note

This example avoids introducing a circular reference between the traceback and a local variable in the current frame by ignoring that part of the return value from exc_info(). If you do need the traceback for some reason (such as to log it), you should explicitly delete the local variable when you’re done (using del) to avoid cycles.

$ python sys_exc_info.py
Handling RuntimeError exception with message "This is the error message" in Thread-2
Handling RuntimeError exception with message "This is the error message" in Thread-1

Previous Interactive Exception

In the interactive interpreter, there is only one thread of interaction. Unhandled exceptions in that thread are saved to three variables in sys (last_type, last_value, and last_traceback) to make it easy to retrieve them for debugging. With the post-mortem debugger in pdb you don’t have to use the values directly.

$ python
Python 2.6.2 (r262:71600, Apr 16 2009, 09:17:39)
[GCC 4.0.1 (Apple Computer, Inc. build 5250)] on darwin
Type "help", "copyright", "credits" or "license" for more information.
>>> def cause_exception():
...   raise RuntimeError('This is the error message')
...
>>> cause_exception()
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "<stdin>", line 2, in cause_exception
RuntimeError: This is the error message
>>> import pdb
>>> pdb.pm()
> <stdin>(2)cause_exception()
(Pdb) where
  <stdin>(1)<module>()
> <stdin>(2)cause_exception()
(Pdb)

See also

exceptions: Built-in errors
pdb: Python debugger
traceback: Module for working with tracebacks.

PyMOTW Home

The canonical version of this article

PyMOTW: sys, Part 3: Memory Management and Limits

2009-10-25T10:50:00.001-04:00

Memory Management and Limits

sys includes several functions for understanding and controlling memory usage.

Reference Counts

Python helps you manage memory with garbage collection. An object is automatically marked to be collected when its reference count drops to zero. To examine the reference count of an existing object, use getrefcount().

import sys

one = []
print 'At start         :', sys.getrefcount(one)

two = one

print 'Second reference :', sys.getrefcount(one)

del two

print 'After del        :', sys.getrefcount(one)

Notice that the count is actually one higher than expected because there is a temporary reference to the object held by getrefcount() itself.

$ python sys_getrefcount.py
At start         : 2
Second reference : 3
After del        : 2

See also

gc: Control the garbage collector via the functions exposed in gc.

Object Size

Knowing how many references an object has may help you figure out where you have a cycle or a leak in your memory, but it isn’t enough to determine what objects are consuming the most memory. For that, you also need to know how big objects are.

import sys

class OldStyle:
    pass

class NewStyle(object):
    pass

for obj in [ [], (), {}, 'c', 'string', 1, 2.3, 
             OldStyle, OldStyle(), NewStyle, NewStyle(),
             ]:
    print '%10s : %s' % (type(obj).__name__, sys.getsizeof(obj))

The size is reported in bytes.

$ python sys_getsizeof.py
      list : 36
     tuple : 28
      dict : 140
       str : 25
       str : 30
       int : 12
     float : 16
  classobj : 48
  instance : 36
      type : 452
  NewStyle : 32

For a more accurate estimate of the space used by a class, you can provide a __sizeof__() method to compute the value by aggregating the sizes of attributes of an object.

import sys

class MyClass(object):
    def __init__(self):
        self.a = 'a'
        self.b = 'b'
        return
    def __sizeof__(self):
        return object.__sizeof__(self) + \
            sum(sys.getsizeof(v) for v in self.__dict__.values())

my_inst = MyClass()
print sys.getsizeof(my_inst)

$ python sys_getsizeof_custom.py
82

Recursion

Allowing infinite recursion in a Python application may introduce a stack overflow in the interpreter itself, leading to a crash. To eliminate this situation, the interpreter lets you control the maximum recursion depth using setrecursionlimit() and getrecursionlimit().

import sys

print 'Initial limit:', sys.getrecursionlimit()

sys.setrecursionlimit(10)

print 'Modified limit:', sys.getrecursionlimit()

def generate_recursion_error(i):
    print 'generate_recursion_error(%s)' % i
    generate_recursion_error(i+1)

try:
    generate_recursion_error(1)
except RuntimeError, err:
    print 'Caught exception:', err

Once the recursion limit is reached, the interpreter raises a RuntimeError exception so your program has an opportunity to handle the situation.

$ python sys_recursionlimit.py
Initial limit: 1000
Modified limit: 10
generate_recursion_error(1)
generate_recursion_error(2)
generate_recursion_error(3)
generate_recursion_error(4)
generate_recursion_error(5)
generate_recursion_error(6)
generate_recursion_error(7)
generate_recursion_error(8)
Caught exception: maximum recursion depth exceeded while getting the str of an object

Maximum Values

Along with the runtime configurable values, sys includes variables defining the maximum values for types that vary from system to system.

import sys

print 'maxint    :', sys.maxint
print 'maxsize   :', sys.maxsize
print 'maxunicode:', sys.maxunicode

maxint is the largest representable regular integer. maxsize is the maximum size of a list, dictionary, string, or other data structure dictated by the C interpreter’s size type. maxunicode is the largest integer Unicode point supported by the interpreter as currently configured.

$ python sys_maximums.py
maxint    : 2147483647
maxsize   : 2147483647
maxunicode: 65535

Floating Point Values

The structure float_info contains information about the floating point type representation used by the interpreter, based on the underlying system’s float implementation.

import sys

print 'Smallest difference (epsilon):', sys.float_info.epsilon
print
print 'Digits (dig)              :', sys.float_info.dig
print 'Mantissa digits (mant_dig):', sys.float_info.mant_dig
print
print 'Maximum (max):', sys.float_info.max
print 'Minimum (min):', sys.float_info.min
print
print 'Radix of exponents (radix):', sys.float_info.radix
print
print 'Maximum exponent for radix (max_exp):', sys.float_info.max_exp
print 'Minimum exponent for radix (min_exp):', sys.float_info.min_exp
print
print 'Maximum exponent for power of 10 (max_10_exp):', sys.float_info.max_10_exp
print 'Minimum exponent for power of 10 (min_10_exp):', sys.float_info.min_10_exp
print
print 'Rounding for addition (rounds):', sys.float_info.rounds

Note

These values depend on the compiler and underlying system, so you may have different results. These examples were produced on OS X 10.5.8.

$ python sys_float_info.py
Smallest difference (epsilon): 2.22044604925e-16

Digits (dig)              : 15
Mantissa digits (mant_dig): 53

Maximum (max): 1.79769313486e+308
Minimum (min): 2.22507385851e-308

Radix of exponents (radix): 2

Maximum exponent for radix (max_exp): 1024
Minimum exponent for radix (min_exp): -1021

Maximum exponent for power of 10 (max_10_exp): 308
Minimum exponent for power of 10 (min_10_exp): -307

Rounding for addition (rounds): 1

See also

Your system’s float.h contains more details about these settings.

PyMOTW Home

The canonical version of this article