#+TITLE: The unreasonable effectiveness of  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.

#+begin_src python :results output :exports both :session fib
def fib(n):
    i, f1, f2 = 1, 1, 1
    while i < n:
        f1, f2 = f2, f1 + f2
        i += 1
    return f1
#+end_src

#+RESULTS:

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.

#+begin_src python :results output :exports both :session fib
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
#+end_src

#+RESULTS:
: Python 3.8.3 (default, May 17 2020, 18:15:42) 
: [GCC 10.1.0] on linux
: Type "help", "copyright", "credits" or "license" for more information.
: >>> python.el: native completion setup loaded

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.

#+begin_src python :results output :exports both :session fib
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)
#+end_src

#+RESULTS:
#+begin_example
| 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}  |
| opcode     | None |    5 |     40 | JUMP_ABSOLUTE      | {'n': 3, 'i': 2, 'f1': 1, 'f2': 2}  |
| line       | None |    3 |     10 | LOAD_FAST          | {'n': 3, 'i': 2, 'f1': 1, 'f2': 2}  |
| opcode     | None |    3 |     10 | LOAD_FAST          | {'n': 3, 'i': 2, 'f1': 1, 'f2': 2}  |
| opcode     | None |    3 |     12 | LOAD_FAST          | {'n': 3, 'i': 2, 'f1': 1, 'f2': 2}  |
| opcode     | None |    3 |     14 | COMPARE_OP         | {'n': 3, 'i': 2, 'f1': 1, 'f2': 2}  |
| opcode     | None |    3 |     16 | POP_JUMP_IF_FALSE  | {'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}  |
| opcode     | None |    5 |     40 | JUMP_ABSOLUTE      | {'n': 3, 'i': 3, 'f1': 2, 'f2': 3}  |
| line       | None |    3 |     10 | LOAD_FAST          | {'n': 3, 'i': 3, 'f1': 2, 'f2': 3}  |
| opcode     | None |    3 |     10 | LOAD_FAST          | {'n': 3, 'i': 3, 'f1': 2, 'f2': 3}  |
| opcode     | None |    3 |     12 | LOAD_FAST          | {'n': 3, 'i': 3, 'f1': 2, 'f2': 3}  |
| opcode     | None |    3 |     14 | COMPARE_OP         | {'n': 3, 'i': 3, 'f1': 2, 'f2': 3}  |
| opcode     | None |    3 |     16 | POP_JUMP_IF_FALSE  | {'n': 3, 'i': 3, 'f1': 2, 'f2': 3}  |
| line       | None |    6 |     42 | LOAD_FAST          | {'n': 3, 'i': 3, 'f1': 2, 'f2': 3}  |
| opcode     | None |    6 |     42 | LOAD_FAST          | {'n': 3, 'i': 3, 'f1': 2, 'f2': 3}  |
| opcode     | None |    6 |     44 | RETURN_VALUE       | {'n': 3, 'i': 3, 'f1': 2, 'f2': 3}  |
| return     |    2 |    6 |     44 | RETURN_VALUE       | {'n': 3, 'i': 3, 'f1': 2, 'f2': 3}  |
#+end_example

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.

#+begin_src python :results output :exports both :session fib
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}")
#+end_src

#+RESULTS:
#+begin_example
field                | value
co_argcount          | 1
co_cellvars          | ()
co_code              | b'd\x01\\\x03}\x01}\x02}\x03|\x01|\x00k\x00r*|\x03|\x02|\x03\x17\x00\x02\x00}\x02}\x03|\x01d\x027\x00}\x01q\n|\x02S\x00'
co_consts            | (None, (1, 1, 1), 1)
co_filename          | /tmp/babel-3mxJ0q/python-hg4TBC
co_firstlineno       | 1
co_flags             | 67
co_freevars          | ()
co_kwonlyargcount    | 0
co_lnotab            | b'\x00\x01\n\x01\x08\x01\x0e\x01\n\x01'
co_name              | fib
co_names             | ()
co_nlocals           | 4
co_posonlyargcount   | 0
co_stacksize         | 3
co_varnames          | ('n', 'i', 'f1', 'f2')
#+end_example


    
* 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. 

#+CAPTION: Visualizing the broken behavior described in [[https://nullprogram.com/blog/2020/05/24/][nullprogram]]
file:../static/images/nullprogram.png

** 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. 

#+begin_src python :results output :exports both
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)}")
#+end_src

#+RESULTS:
: 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.
  
* Comments?
Drop me an email or reach out on Twitter.

* History
-  2020-06-13: Published.
-  (TODO Explore  =PyEval_SetTrace=.)