sys.settrace and sys.setprofile

CPython allows for incredible introspection: settrace and setprofile can observe and control just about everything from within the program. The official documentation doesn’t do enough justice to these functions, and so I decided to take a stab at it.

sys.settrace sets a trace function that is triggered by the VM every time it enters or exits a function, processes a line of code, runs into an exception and even when it runs a single opcode. Each of these callbacks also give full access to the current stack frame and code.

sys.setprofile sets a trace function that’s triggered every time the VM enters or exits both Python and C functions.

There are equivalents available in the threading module to allow setting tracers for multi-threaded programs as well: threading.settrace and threading.setprofile.

The frame object contains the current state of computation: all locals, globals, current location, etc.; the code object has the actual opcodes and function details independent of the current stack.

Frighteningly enough, it’s also possible to modify the state of the program using the frame: so it’s possible to override locals, globals, or simply skip around by changing the offset into the bytecode.

Cheat Sheet
sys.settrace(fn) and sys.setprofile(fn) to set fn as the callback.
sys.settrace(None) and sys.setprofile(None) to clear it.
The trace function has the function signature (frame, event, arg).
settrace events: call, return, line, exception, opcode
setprofile events: call, c_call, return, c_return, c_exception
The return value is used in all but return to specify the new local trace function for settrace, and is unused for setprofile.
arg depends on the event
c_call, c_return, c_exception: C function object
return: The return value, None for exceptions
exception: (exception, value, traceback) tuple
frame fields
f_back: previous frame
f_code: code object
f_locals: as title
f_globals: as title
f_builtins: built-in names
f_lasti: instruction, index into bytecode string
f_trace: writable, set the trace function for this frame
f_trace_lines: writable, trigger trace for each line
f_trace_opcodes: writable, trigger trace for each opcode
f_lineno: writable, current line number
code fields (immutable)
co_name: function name
co_argcount: positional arguments
co_posonlargcount: positional-only arguments
co_kwonlyargcount: keyword-only arguments
co_nlocals: # of local variables used by the function, including args
co_varnames: tuple with names of local variables
co_cellvars: tuple with local vars referred to by nested functions
co_freevars: tuple with free variables
co_code: bytecode as a string
co_consts: tuple with literals used by bytecode
first item is docstring or None for functions
co_names: tuple with names used by bytecode
co_filename: origin filename
co_firstlineno: first line number of function
co_lnotab: maps bytecode offsets to line numbers
co_flags: flags for interpreter
0x04: uses *arguments
0x08: uses **keywords
0x20: generator
0x2000: from future import division
A full example of a settrace
A short Fibonacci loop serves as a good example to show the values inside a trace.

def fib(n):
    i, f1, f2 = 1, 1, 1
    while i < n:
        f1, f2 = f2, f1 + f2
        i += 1
    return f1

show_trace is a simple tracing function to give a live example. Note that f_trace_opcodes needs to be explicitly set to True to trace opcodes in the frame, and import opcode gets the opcode number to name mapping.

import opcode  


def show_trace(frame, event, arg):
    frame.f_trace_opcodes = True
    code = frame.f_code
    offset = frame.f_lasti
    print(f"| {event:10} | {str(arg):>4} |", end=' ')
    print(f"{frame.f_lineno:>4} | {frame.f_lasti:>6} |", end=' ')
    print(f"{opcode.opname[code.co_code[offset]]:<18} | {str(frame.f_locals):<35} |")
    return show_trace

Finally, actually triggering the trace – and pretty printing the output. Here we see the bytecode actually being executed; in contrast, dis.dis shows the disassembled bytecode representing the function.

import sys

header = f"| {'event':10} | {'arg':>4} | line | offset | {'opcode':^18} | {'locals':^35} |"
print(header)
sys.settrace(show_trace)
fib(3)
sys.settrace(None)
event arg line offset opcode locals
call None 1 -1 <0> {‘n’: 3}
line None 2 0 LOAD_CONST {‘n’: 3}
opcode None 2 0 LOAD_CONST {‘n’: 3}
opcode None 2 2 UNPACK_SEQUENCE {‘n’: 3}
opcode None 2 4 STORE_FAST {‘n’: 3}
opcode None 2 6 STORE_FAST {‘n’: 3, ‘i’: 1}
opcode None 2 8 STORE_FAST {‘n’: 3, ‘i’: 1, ‘f1’: 1}
line None 3 10 LOAD_FAST {‘n’: 3, ‘i’: 1, ‘f1’: 1, ‘f2’: 1}
opcode None 3 10 LOAD_FAST {‘n’: 3, ‘i’: 1, ‘f1’: 1, ‘f2’: 1}
opcode None 3 12 LOAD_FAST {‘n’: 3, ‘i’: 1, ‘f1’: 1, ‘f2’: 1}
opcode None 3 14 COMPARE_OP {‘n’: 3, ‘i’: 1, ‘f1’: 1, ‘f2’: 1}
opcode None 3 16 POP_JUMP_IF_FALSE {‘n’: 3, ‘i’: 1, ‘f1’: 1, ‘f2’: 1}
line None 4 18 LOAD_FAST {‘n’: 3, ‘i’: 1, ‘f1’: 1, ‘f2’: 1}
opcode None 4 18 LOAD_FAST {‘n’: 3, ‘i’: 1, ‘f1’: 1, ‘f2’: 1}
opcode None 4 20 LOAD_FAST {‘n’: 3, ‘i’: 1, ‘f1’: 1, ‘f2’: 1}
opcode None 4 22 LOAD_FAST {‘n’: 3, ‘i’: 1, ‘f1’: 1, ‘f2’: 1}
opcode None 4 24 BINARY_ADD {‘n’: 3, ‘i’: 1, ‘f1’: 1, ‘f2’: 1}
opcode None 4 26 ROT_TWO {‘n’: 3, ‘i’: 1, ‘f1’: 1, ‘f2’: 1}
opcode None 4 28 STORE_FAST {‘n’: 3, ‘i’: 1, ‘f1’: 1, ‘f2’: 1}
opcode None 4 30 STORE_FAST {‘n’: 3, ‘i’: 1, ‘f1’: 1, ‘f2’: 1}
line None 5 32 LOAD_FAST {‘n’: 3, ‘i’: 1, ‘f1’: 1, ‘f2’: 2}
opcode None 5 32 LOAD_FAST {‘n’: 3, ‘i’: 1, ‘f1’: 1, ‘f2’: 2}
opcode None 5 34 LOAD_CONST {‘n’: 3, ‘i’: 1, ‘f1’: 1, ‘f2’: 2}
opcode None 5 36 INPLACE_ADD {‘n’: 3, ‘i’: 1, ‘f1’: 1, ‘f2’: 2}
opcode None 5 38 STORE_FAST {‘n’: 3, ‘i’: 1, ‘f1’: 1, ‘f2’: 2}
line None 3 40 LOAD_FAST {‘n’: 3, ‘i’: 2, ‘f1’: 1, ‘f2’: 2}
opcode None 3 40 LOAD_FAST {‘n’: 3, ‘i’: 2, ‘f1’: 1, ‘f2’: 2}
opcode None 3 42 LOAD_FAST {‘n’: 3, ‘i’: 2, ‘f1’: 1, ‘f2’: 2}
opcode None 3 44 COMPARE_OP {‘n’: 3, ‘i’: 2, ‘f1’: 1, ‘f2’: 2}
opcode None 3 46 POP_JUMP_IF_TRUE {‘n’: 3, ‘i’: 2, ‘f1’: 1, ‘f2’: 2}
line None 4 18 LOAD_FAST {‘n’: 3, ‘i’: 2, ‘f1’: 1, ‘f2’: 2}
opcode None 4 18 LOAD_FAST {‘n’: 3, ‘i’: 2, ‘f1’: 1, ‘f2’: 2}
opcode None 4 20 LOAD_FAST {‘n’: 3, ‘i’: 2, ‘f1’: 1, ‘f2’: 2}
opcode None 4 22 LOAD_FAST {‘n’: 3, ‘i’: 2, ‘f1’: 1, ‘f2’: 2}
opcode None 4 24 BINARY_ADD {‘n’: 3, ‘i’: 2, ‘f1’: 1, ‘f2’: 2}
opcode None 4 26 ROT_TWO {‘n’: 3, ‘i’: 2, ‘f1’: 1, ‘f2’: 2}
opcode None 4 28 STORE_FAST {‘n’: 3, ‘i’: 2, ‘f1’: 1, ‘f2’: 2}
opcode None 4 30 STORE_FAST {‘n’: 3, ‘i’: 2, ‘f1’: 2, ‘f2’: 2}
line None 5 32 LOAD_FAST {‘n’: 3, ‘i’: 2, ‘f1’: 2, ‘f2’: 3}
opcode None 5 32 LOAD_FAST {‘n’: 3, ‘i’: 2, ‘f1’: 2, ‘f2’: 3}
opcode None 5 34 LOAD_CONST {‘n’: 3, ‘i’: 2, ‘f1’: 2, ‘f2’: 3}
opcode None 5 36 INPLACE_ADD {‘n’: 3, ‘i’: 2, ‘f1’: 2, ‘f2’: 3}
opcode None 5 38 STORE_FAST {‘n’: 3, ‘i’: 2, ‘f1’: 2, ‘f2’: 3}
line None 3 40 LOAD_FAST {‘n’: 3, ‘i’: 3, ‘f1’: 2, ‘f2’: 3}
opcode None 3 40 LOAD_FAST {‘n’: 3, ‘i’: 3, ‘f1’: 2, ‘f2’: 3}
opcode None 3 42 LOAD_FAST {‘n’: 3, ‘i’: 3, ‘f1’: 2, ‘f2’: 3}
opcode None 3 44 COMPARE_OP {‘n’: 3, ‘i’: 3, ‘f1’: 2, ‘f2’: 3}
opcode None 3 46 POP_JUMP_IF_TRUE {‘n’: 3, ‘i’: 3, ‘f1’: 2, ‘f2’: 3}
line None 6 48 LOAD_FAST {‘n’: 3, ‘i’: 3, ‘f1’: 2, ‘f2’: 3}
opcode None 6 48 LOAD_FAST {‘n’: 3, ‘i’: 3, ‘f1’: 2, ‘f2’: 3}
opcode None 6 50 RETURN_VALUE {‘n’: 3, ‘i’: 3, ‘f1’: 2, ‘f2’: 3}
return 2 6 50 RETURN_VALUE {‘n’: 3, ‘i’: 3, ‘f1’: 2, ‘f2’: 3}

The underlying code of a function is directly accessible with the code field, and is also the value stored in the frame’s co_code field.

import inspect

code = fib.__code__
print(f"{'field':<20} | value")
for name, val in inspect.getmembers(code):
    if name.startswith("co_"):
        print(f"{name:<20} | {val}")
field value
co_argcount 1
co_cellvars ()
co_code b’d\x01\\x03}\x01}\x02}\x03
co_consts (None, (1, 1, 1), 1)
co_filename /tmp/python-5ZeoZC
co_firstlineno 1
co_flags 67
co_freevars ()
co_kwonlyargcount 0
co_lines <built-in method co_lines of code object at 0x7f81d2aab1b0>
co_linetable b’\n\x01\x08\x01\x0e\x01\x08\x01\x08\xfe\x04\x03’
co_lnotab b’\x00\x01\n\x01\x08\x01\x0e\x01\x08\xfe\x08\x03’
co_name fib
co_names ()
co_nlocals 4
co_posonlyargcount 0
co_stacksize 3
co_varnames (‘n’, ‘i’, ‘f1’, ‘f2’)

Potentially useful patterns
A completely programmable ad-hoc debugger
I’ve found settrace with a simple function to be extremely valuable in understanding code.

Instead of learning even more arcane commands and manually stepping through programs with pdb, I can directly write my “pause” and “inspect” logic into the trace function and keep iterating on the program – while also filtering the output to files I care about.

The tracer module also helps with directly tracing and dumping the code, but I generally find it too unwieldy compared to directly using settrace.

Building code execution visualizations
Working on mine is what inspired this note: it’s not hard to imagine beautiful ways to display code execution. My approach is to use Catapult (chrome://tracing) for rendering the execution, but it could just as easily be on the source itself inside an IDE.

nullprogram.png

Figure 1: Visualizing the broken behavior described in nullprogram

Test coverage
settrace makes it trivial to observe the lines of code executed in any specific program run, and the underling C function is how coverage.py works.

They didn’t stop to think if they should
Jump to arbitrary parts of a function
I vaguely remember seeing a Hacker News post about jump implemented with settrace and then directly writing to the frame offset.

Recreating that is left as an exercise to the reader.

Rewrite arguments on the fly
For bonus points, you can include this code and have it trigger randomly.

import sys

def square_arguments(frame, event, arg):
    if event != "call":
        return

    code = frame.f_code
    if code.co_name != "add":
        return

    for var in frame.f_locals:
        frame.f_locals[var] = frame.f_locals[var] ** 2

def add(a, b):
    return a + b

print(f"add(1, 2): {add(1, 2)}")

sys.settrace(square_arguments)
print(f"add(1, 2): {add(1, 2)}")
add(1, 2): 3
add(1, 2): 5

Not quite a deus-ex machina
Tracing doesn’t capture coroutine creation, which would be amazing. With sys.set_coroutine_origin_tracking it’s possible to get a stack trace to where a specific coroutine was created, but I’d love for that step to also pass through settrace / setprofile.

It’s also not directly possible to set this from outside an arbitrary running program that I know of.

Finally, setprofile intercepts and shares exceptions thrown from C code, but doesn’t intercept Python exceptions. I’m not quite sure why.

References
sys.settrace in the standard python documentation.
The Python Type Hierarchy, with definitions of frame and code objects.
inspect, with very readable documentation that makes my cheat sheet irrelevant.

原文地址:The unreasonable effectiveness of sys.settrace (and sys.setprofile)

关闭