gh-91462: Make lltrace output human-readable. (GH-91463)

* Transform opcodes into opnames
* Print the whole stack at each opcode, and eliminate prtrace output at each (push/pop/stackadj)
* Display info about the function at each resume_frame

Lib/test/test_lltrace.py

@@ -1,21 +1,103 @@
-import os
+import dis
+import sys
 import textwrap
 import unittest
 
-from test.support import os_helper
+from test.support import os_helper, verbose
 from test.support.script_helper import assert_python_ok
 
+def example():
+    x = []
+    for i in range(1):
+        x.append(i)
+    x = "this is"
+    y = "an example"
+    print(x, y)
 
+Py_DEBUG = hasattr(sys, 'gettotalrefcount')
+
+@unittest.skipUnless(Py_DEBUG, "lltrace requires Py_DEBUG")
 class TestLLTrace(unittest.TestCase):
 
+    def run_code(self, code):
+        code = textwrap.dedent(code).strip()
+        with open(os_helper.TESTFN, 'w', encoding='utf-8') as fd:
+            self.addCleanup(os_helper.unlink, os_helper.TESTFN)
+            fd.write(code)
+        status, stdout, stderr = assert_python_ok(os_helper.TESTFN)
+        self.assertEqual(stderr, b"")
+        self.assertEqual(status, 0)
+        result = stdout.decode('utf-8')
+        if verbose:
+            print("\n\n--- code ---")
+            print(code)
+            print("\n--- stdout ---")
+            print(result)
+            print()
+        return result
+
+    def test_lltrace(self):
+        stdout = self.run_code("""
+            def dont_trace_1():
+                a = "a"
+                a = 10 * a
+            def trace_me():
+                for i in range(3):
+                    +i
+            def dont_trace_2():
+                x = 42
+                y = -x
+            dont_trace_1()
+            __ltrace__ = 1
+            trace_me()
+            del __ltrace__
+            dont_trace_2()
+        """)
+        self.assertIn("GET_ITER", stdout)
+        self.assertIn("FOR_ITER", stdout)
+        self.assertIn("UNARY_POSITIVE", stdout)
+        self.assertIn("POP_TOP", stdout)
+        self.assertNotIn("BINARY_OP", stdout)
+        self.assertNotIn("UNARY_NEGATIVE", stdout)
+
+        self.assertIn("'trace_me' in module '__main__'", stdout)
+        self.assertNotIn("dont_trace_1", stdout)
+        self.assertNotIn("'dont_trace_2' in module", stdout)
+
+    def test_lltrace_different_module(self):
+        stdout = self.run_code("""
+            from test import test_lltrace
+            test_lltrace.__ltrace__ = 1
+            test_lltrace.example()
+        """)
+        self.assertIn("'example' in module 'test.test_lltrace'", stdout)
+        self.assertIn('LOAD_CONST', stdout)
+        self.assertIn('FOR_ITER', stdout)
+        self.assertIn('this is an example', stdout)
+
+        # check that offsets match the output of dis.dis()
+        instr_map = {i.offset: i for i in dis.get_instructions(example)}
+        for line in stdout.splitlines():
+            offset, colon, opname_oparg = line.partition(":")
+            if not colon:
+                continue
+            offset = int(offset)
+            opname_oparg = opname_oparg.split()
+            if len(opname_oparg) == 2:
+                opname, oparg = opname_oparg
+                oparg = int(oparg)
+            else:
+                (opname,) = opname_oparg
+                oparg = None
+            self.assertEqual(instr_map[offset].opname, opname)
+            self.assertEqual(instr_map[offset].arg, oparg)
+
     def test_lltrace_does_not_crash_on_subscript_operator(self):
         # If this test fails, it will reproduce a crash reported as
         # bpo-34113. The crash happened at the command line console of
         # debug Python builds with __ltrace__ enabled (only possible in console),
         # when the internal Python stack was negatively adjusted
-        with open(os_helper.TESTFN, 'w', encoding='utf-8') as fd:
+        stdout = self.run_code("""
-            self.addCleanup(os_helper.unlink, os_helper.TESTFN)
-            fd.write(textwrap.dedent("""\
             import code
 
             console = code.InteractiveConsole()
@@ -23,9 +105,8 @@ class TestLLTrace(unittest.TestCase):
             console.push('a = [1, 2, 3]')
             console.push('a[0] = 1')
             print('unreachable if bug exists')
-            """))
+        """)
-
+        self.assertIn("unreachable if bug exists", stdout)
-            assert_python_ok(os_helper.TESTFN)
 
 if __name__ == "__main__":
     unittest.main()

Misc/NEWS.d/next/Core and Builtins/2022-04-12-00-44-14.gh-issue-91462.t8oxyd.rst

@@ -0,0 +1 @@
+Make the interpreter's low-level tracing (lltrace) feature output more readable by displaying opcode names (rather than just numbers), and by displaying stack contents before each opcode.

Python/ceval.c

@@ -54,15 +54,77 @@ static PyObject * do_call_core(
 
 #ifdef LLTRACE
 static int lltrace;
-static int prtrace(PyThreadState *, PyObject *, const char *);
+static void
-static void lltrace_instruction(_PyInterpreterFrame *frame, int opcode, int oparg)
+dump_stack(_PyInterpreterFrame *frame, PyObject **stack_pointer)
 {
+    PyObject **stack_base = _PyFrame_Stackbase(frame);
+    PyObject *type, *value, *traceback;
+    PyErr_Fetch(&type, &value, &traceback);
+    printf("    stack=[");
+    for (PyObject **ptr = stack_base; ptr < stack_pointer; ptr++) {
+        if (ptr != stack_base) {
+            printf(", ");
+        }
+        if (PyObject_Print(*ptr, stdout, 0) != 0) {
+            PyErr_Clear();
+            printf("<%s object at %p>",
+                   Py_TYPE(*ptr)->tp_name, (void *)(*ptr));
+        }
+    }
+    printf("]\n");
+    fflush(stdout);
+    PyErr_Restore(type, value, traceback);
+}
+
+static void
+lltrace_instruction(_PyInterpreterFrame *frame,
+                    PyObject **stack_pointer,
+                    _Py_CODEUNIT *next_instr)
+{
+    dump_stack(frame, stack_pointer);
+    int oparg = _Py_OPARG(*next_instr);
+    int opcode = _Py_OPCODE(*next_instr);
+    const char *opname = _PyOpcode_OpName[opcode];
+    assert(opname != NULL);
+    int offset = (int)(next_instr - _PyCode_CODE(frame->f_code));
     if (HAS_ARG(opcode)) {
-        printf("%d: %d, %d\n", _PyInterpreterFrame_LASTI(frame), opcode, oparg);
+        printf("%d: %s %d\n", offset * 2, opname, oparg);
     }
     else {
-        printf("%d: %d\n", _PyInterpreterFrame_LASTI(frame), opcode);
+        printf("%d: %s\n", offset * 2, opname);
     }
+    fflush(stdout);
+}
+static void
+lltrace_resume_frame(_PyInterpreterFrame *frame)
+{
+    PyFunctionObject *f = frame->f_func;
+    if (f == NULL) {
+        printf("\nResuming frame.");
+        return;
+    }
+    PyObject *type, *value, *traceback;
+    PyErr_Fetch(&type, &value, &traceback);
+    PyObject *name = f->func_qualname;
+    if (name == NULL) {
+        name = f->func_name;
+    }
+    printf("\nResuming frame");
+    if (name) {
+        printf(" for ");
+        if (PyObject_Print(name, stdout, 0) < 0) {
+            PyErr_Clear();
+        }
+    }
+    if (f->func_module) {
+        printf(" in module ");
+        if (PyObject_Print(f->func_module, stdout, 0) < 0) {
+            PyErr_Clear();
+        }
+    }
+    printf("\n");
+    fflush(stdout);
+    PyErr_Restore(type, value, traceback);
 }
 #endif
 static int call_trace(Py_tracefunc, PyObject *,
@@ -1266,7 +1328,8 @@ eval_frame_handle_pending(PyThreadState *tstate)
 
 /* PRE_DISPATCH_GOTO() does lltrace if enabled. Normally a no-op */
 #ifdef LLTRACE
-#define PRE_DISPATCH_GOTO() if (lltrace) { lltrace_instruction(frame, opcode, oparg); }
+#define PRE_DISPATCH_GOTO() if (lltrace) { \
+    lltrace_instruction(frame, stack_pointer, next_instr); }
 #else
 #define PRE_DISPATCH_GOTO() ((void)0)
 #endif
@@ -1375,6 +1438,7 @@ eval_frame_handle_pending(PyThreadState *tstate)
 /* The stack can grow at most MAXINT deep, as co_nlocals and
    co_stacksize are ints. */
 #define STACK_LEVEL()     ((int)(stack_pointer - _PyFrame_Stackbase(frame)))
+#define STACK_SIZE()      (frame->f_code->co_stacksize)
 #define EMPTY()           (STACK_LEVEL() == 0)
 #define TOP()             (stack_pointer[-1])
 #define SECOND()          (stack_pointer[-2])
@@ -1387,23 +1451,21 @@ eval_frame_handle_pending(PyThreadState *tstate)
 #define BASIC_PUSH(v)     (*stack_pointer++ = (v))
 #define BASIC_POP()       (*--stack_pointer)
 
-#ifdef LLTRACE
+#ifdef Py_DEBUG
-#define PUSH(v)         { (void)(BASIC_PUSH(v), \
+#define PUSH(v)         do { \
-                          lltrace && prtrace(tstate, TOP(), "push")); \
+                            BASIC_PUSH(v); \
-                          assert(STACK_LEVEL() <= frame->f_code->co_stacksize); }
+                            assert(STACK_LEVEL() <= STACK_SIZE()); \
-#define POP()           ((void)(lltrace && prtrace(tstate, TOP(), "pop")), \
+                        } while (0)
-                         BASIC_POP())
+#define POP()           (assert(STACK_LEVEL() > 0), BASIC_POP())
 #define STACK_GROW(n)   do { \
                             assert(n >= 0); \
-                          (void)(BASIC_STACKADJ(n), \
+                            BASIC_STACKADJ(n); \
-                          lltrace && prtrace(tstate, TOP(), "stackadj")); \
+                            assert(STACK_LEVEL() <= STACK_SIZE()); \
-                          assert(STACK_LEVEL() <= frame->f_code->co_stacksize); \
                         } while (0)
 #define STACK_SHRINK(n) do { \
                             assert(n >= 0); \
-                            (void)(lltrace && prtrace(tstate, TOP(), "stackadj")); \
+                            assert(STACK_LEVEL() >= n); \
-                            (void)(BASIC_STACKADJ(-(n))); \
+                            BASIC_STACKADJ(-(n)); \
-                            assert(STACK_LEVEL() <= frame->f_code->co_stacksize); \
                         } while (0)
 #else
 #define PUSH(v)                BASIC_PUSH(v)
@@ -1673,6 +1735,9 @@ resume_frame:
         }
         lltrace = r;
     }
+    if (lltrace) {
+        lltrace_resume_frame(frame);
+    }
 #endif
 
 #ifdef Py_DEBUG
@@ -6663,23 +6728,6 @@ Error:
     return 0;
 }
 
-#ifdef LLTRACE
-static int
-prtrace(PyThreadState *tstate, PyObject *v, const char *str)
-{
-    printf("%s ", str);
-    PyObject *type, *value, *traceback;
-    PyErr_Fetch(&type, &value, &traceback);
-    if (PyObject_Print(v, stdout, 0) != 0) {
-        /* Don't know what else to do */
-        _PyErr_Clear(tstate);
-    }
-    printf("\n");
-    PyErr_Restore(type, value, traceback);
-    return 1;
-}
-#endif
-
 static void
 call_exc_trace(Py_tracefunc func, PyObject *self,
                PyThreadState *tstate,