Commits

Even Wiik Thomassen  committed 2f50108

Added howto on PYPYLOG from Carl F Boltz.

  • Participants
  • Parent commits 89cb2fb

Comments (0)

Files changed (1)

File docs/pypylog.txt

+Reading JIT low level traces
+=============================
+
+To read traces generated by the JIT, you need to run the executable compiled to
+C with an environment variable set::
+
+    PYPYLOG=jit-log-opt:outfile pypy script.py
+
+This does not work only for the ``pypy`` executable, but other for other
+interpreters written with RPython. The syntax of the ``PYPYLOG`` variable is as
+follows: ``category:filename`` The ``category`` is which logging category
+should be written to file ``filename``. For reading JIT traces, ``jit-log-opt``
+is most useful.
+
+Afterwards the file ``outfile`` is created. It contains the intermediate
+representation of the traces that the JIT produces. They are in an ASCII format
+that takes some time to get used to. Every loop the tracer produces
+schematically looks like this::
+
+    [edad93ebdb] {jit-log-opt-loop
+    # Loop 0 (function_name) : loop with 105 ops
+    [p0, p1]
+    ...
+    lots of operations
+    ...
+    +508: jump(p3, p5, descr=TargetToken(-1224430960))
+    +525: --end of the loop--
+    [edada7f7d5] jit-log-opt-loop}
+
+The variables ``[p0, p1]`` in square brachets are the arguments to the trace
+(like function arguments). They are followed by the operations within the
+trace. The trace ends with a ``jump`` operation, that often jumps back to the
+beginning of the loop, or a ``finish`` operation, that ends executing the
+trace.
+
+The operations within the trace are structured with the help of
+``debug_merge_point`` operations. They correspond to the tracer hitting a
+``jit_merge_point`` instruction. Thus the operations that come after a
+``debug_merge_point`` correspond to the trace of one bytecode::
+
+    debug_merge_point(0, 0, '<code object _optimize_charset. file '/home/cfbolz/bin/pypy-c-jit-56445-606d6a6c708f-linux/lib-python/2.7/sre_compile.py'. line 207> #274 FOR_ITER')
+    +232: guard_value(i4, 15, descr=<Guard4>) [i4, p1, p0, p2, p3, p5, i6, i7, p10, p12, p14, p16, p18, p20, p22, p24, p26, p28, p30, p32, p34, p36, p38, p40, p42, p44, p46, p48, p50, p52, p54, p56]
+    +241: guard_class(p38, 151841984, descr=<Guard5>) [p1, p0, p38, p2, p3, p5, i6, p10, p12, p14, p16, p18, p20, p22, p24, p26, p28, p30, p32, p34, p36, p40, p42, p44, p46, p48, p50, p52, p54, p56]
+    +257: p60 = getfield_gc(p38, descr=<FieldP pypy.objspace.std.iterobject.W_AbstractSeqIterObject.inst_w_seq 12>)
+    +260: guard_nonnull(p60, descr=<Guard6>) [p1, p0, p38, p60, p2, p3, p5, i6, p10, p12, p14, p16, p18, p20, p22, p24, p26, p28, p30, p32, p34, p36, p40, p42, p44, p46, p48, p50, p52, p54, p56]
+    +268: i61 = getfield_gc(p38, descr=<FieldS pypy.objspace.std.iterobject.W_AbstractSeqIterObject.inst_index 8>)
+    +271: p62 = getfield_gc(p60, descr=<FieldP pypy.objspace.std.listobject.W_ListObject.inst_strategy 12>)
+    +274: guard_class(p62, 151882912, descr=<Guard7>) [p1, p0, p38, i61, p62, p60, p2, p3, p5, i6, p10, p12, p14, p16, p18, p20, p22, p24, p26, p28, p30, p32, p34, p36, p40, p42, p44, p46, p48, p50, p52, p54, p56]
+    +287: p64 = getfield_gc(p60, descr=<FieldP pypy.objspace.std.listobject.W_ListObject.inst_lstorage 8>)
+    +290: i65 = getfield_gc(p64, descr=<FieldS list.length 4>)
+    +293: i66 = uint_ge(i61, i65)
+    guard_false(i66, descr=<Guard8>) [p1, p0, p38, i61, i65, p64, p2, p3, p5, i6, p10, p12, p14, p16, p18, p20, p22, p24, p26, p28, p30, p32, p34, p36, p40, p42, p44, p46, p48, p50, p52, p54, p56]
+    +301: p67 = getfield_gc(p64, descr=<FieldP list.items 8>)
+    +304: i68 = getarrayitem_gc(p67, i61, descr=<ArrayS 4>)
+    +308: i70 = int_add(i61, 1)
+    +311: setfield_gc(p38, i70, descr=<FieldS pypy.objspace.std.iterobject.W_AbstractSeqIterObject.inst_index 8>)
+    +314: guard_value(i6, 0, descr=<Guard9>) [i6, p1, p0, p2, p3, p5, p10, p12, p14, p16, p18, p20, p22, p24, p26, p28, p30, p32, p34, p36, p38, p42, p44, p46, p48, p50, p52, p54, p56, i68]
+    debug_merge_point(0, 0, '<code object _optimize_charset. file '/home/cfbolz/bin/pypy-c-jit-56445-606d6a6c708f-linux/lib-python/2.7/sre_compile.py'. line 207> #277 STORE_FAST')
+    debug_merge_point(0, 0, '<code object _optimize_charset. file '/home/cfbolz/bin/pypy-c-jit-56445-606d6a6c708f-linux/lib-python/2.7/sre_compile.py'. line 207> #280 LOAD_FAST')
+    debug_merge_point(0, 0, '<code object _optimize_charset. file '/home/cfbolz/bin/pypy-c-jit-56445-606d6a6c708f-linux/lib-python/2.7/sre_compile.py'. line 207> #283 POP_JUMP_IF_FALSE')
+
+This is an example from the Python interpreter, of a small part of a trace.
+Most of the trace are operations for the ``FOR_ITER`` bytecode in the
+``_optimize_charset`` function. The ``STORE_FAST`` and ``LOAD_FAST`` bytecodes
+produced no operations at all.
+
+Operation are in the form ``+num: resvar = op(arg1, arg2, arg2, descr=<descr>)``. The numeric offset at the beginning of the line can be ignored. ``resvar =`` is optional and does not appear for operations without result, so is the presence of a ``descr``.