Various small improvements to uop debug output (python#112218)

- Show uop name in Error/DEOPT messages - Add target to some messages - Expose uop_name() as _PyUopName()
Glyphack · Jan 27, 2024 · 84c2c37 · 84c2c37
1 parent 4b85885
commit 84c2c37
Show file tree

Hide file tree

Showing 2 changed files with 20 additions and 13 deletions.
diff --git a/Python/ceval.c b/Python/ceval.c
@@ -647,6 +647,8 @@ static const _Py_CODEUNIT _Py_INTERPRETER_TRAMPOLINE_INSTRUCTIONS[] = {
 
 extern const struct _PyCode_DEF(8) _Py_InitCleanup;
 
+extern const char *_PyUopName(int index);
+
 /* Disable unused label warnings.  They are handy for debugging, even
    if computed gotos aren't used. */
 
@@ -1002,11 +1004,12 @@ _PyEval_EvalFrameDefault(PyThreadState *tstate, _PyInterpreterFrame *frame, int
         oparg = next_uop->oparg;
         operand = next_uop->operand;
         DPRINTF(3,
-                "%4d: uop %s, oparg %d, operand %" PRIu64 ", stack_level %d\n",
+                "%4d: uop %s, oparg %d, operand %" PRIu64 ", target %d, stack_level %d\n",
                 (int)(next_uop - current_executor->trace),
-                opcode < 256 ? _PyOpcode_OpName[opcode] : _PyOpcode_uop_name[opcode],
+                _PyUopName(opcode),
                 oparg,
                 operand,
+                next_uop->target,
                 (int)(stack_pointer - _PyFrame_Stackbase(frame)));
         next_uop++;
         OPT_STAT_INC(uops_executed);
@@ -1051,7 +1054,9 @@ _PyEval_EvalFrameDefault(PyThreadState *tstate, _PyInterpreterFrame *frame, int
 pop_1_error_tier_two:
     STACK_SHRINK(1);
 error_tier_two:
-    DPRINTF(2, "Error: [Opcode %d, operand %" PRIu64 "]\n", opcode, operand);
+    DPRINTF(2, "Error: [Uop %d (%s), oparg %d, operand %" PRIu64 ", target %d @ %d]\n",
+            opcode, _PyUopName(opcode), oparg, operand, next_uop[-1].target,
+            (int)(next_uop - current_executor->trace - 1));
     OPT_HIST(trace_uop_execution_counter, trace_run_length_hist);
     frame->return_offset = 0;  // Don't leave this random
     _PyFrame_SetStackPointer(frame, stack_pointer);
@@ -1062,7 +1067,9 @@ _PyEval_EvalFrameDefault(PyThreadState *tstate, _PyInterpreterFrame *frame, int
 deoptimize:
     // On DEOPT_IF we just repeat the last instruction.
     // This presumes nothing was popped from the stack (nor pushed).
-    DPRINTF(2, "DEOPT: [Opcode %d, operand %" PRIu64 " @ %d]\n", opcode, operand, (int)(next_uop-current_executor->trace-1));
+    DPRINTF(2, "DEOPT: [Uop %d (%s), oparg %d, operand %" PRIu64 ", target %d @ %d]\n",
+            opcode, _PyUopName(opcode), oparg, operand, next_uop[-1].target,
+            (int)(next_uop - current_executor->trace - 1));
     OPT_HIST(trace_uop_execution_counter, trace_run_length_hist);
     UOP_STAT_INC(opcode, miss);
     frame->return_offset = 0;  // Dispatch to frame->instr_ptr

diff --git a/Python/optimizer.c b/Python/optimizer.c
@@ -324,8 +324,8 @@ uop_dealloc(_PyUOpExecutorObject *self) {
     PyObject_Free(self);
 }
 
-static const char *
-uop_name(int index)
+const char *
+_PyUopName(int index)
 {
     if (index <= MAX_REAL_OPCODE) {
         return _PyOpcode_OpName[index];
@@ -347,7 +347,7 @@ uop_item(_PyUOpExecutorObject *self, Py_ssize_t index)
         PyErr_SetNone(PyExc_IndexError);
         return NULL;
     }
-    const char *name = uop_name(self->trace[index].opcode);
+    const char *name = _PyUopName(self->trace[index].opcode);
     if (name == NULL) {
         name = "<nil>";
     }
@@ -451,7 +451,7 @@ translate_bytecode_to_trace(
 #define ADD_TO_TRACE(OPCODE, OPARG, OPERAND, TARGET) \
     DPRINTF(2, \
             "  ADD_TO_TRACE(%s, %d, %" PRIu64 ")\n", \
-            uop_name(OPCODE), \
+            _PyUopName(OPCODE), \
             (OPARG), \
             (uint64_t)(OPERAND)); \
     assert(trace_length < max_length); \
@@ -477,7 +477,7 @@ translate_bytecode_to_trace(
     reserved = (n);  // Keep ADD_TO_TRACE honest
 
 // Reserve space for main+stub uops, plus 3 for _SET_IP, _CHECK_VALIDITY and _EXIT_TRACE
-#define RESERVE(main, stub) RESERVE_RAW((main) + (stub) + 3, uop_name(opcode))
+#define RESERVE(main, stub) RESERVE_RAW((main) + (stub) + 3, _PyUopName(opcode))
 
 // Trace stack operations (used by _PUSH_FRAME, _POP_FRAME)
 #define TRACE_STACK_PUSH() \
@@ -549,8 +549,8 @@ translate_bytecode_to_trace(
                 uint32_t uopcode = BRANCH_TO_GUARD[opcode - POP_JUMP_IF_FALSE][jump_likely];
                 _Py_CODEUNIT *next_instr = instr + 1 + _PyOpcode_Caches[_PyOpcode_Deopt[opcode]];
                 DPRINTF(4, "%s(%d): counter=%x, bitcount=%d, likely=%d, uopcode=%s\n",
-                        uop_name(opcode), oparg,
-                        counter, bitcount, jump_likely, uop_name(uopcode));
+                        _PyUopName(opcode), oparg,
+                        counter, bitcount, jump_likely, _PyUopName(uopcode));
                 ADD_TO_TRACE(uopcode, max_length, 0, target);
                 if (jump_likely) {
                     _Py_CODEUNIT *target_instr = next_instr + oparg;
@@ -710,7 +710,7 @@ translate_bytecode_to_trace(
                     }
                     break;
                 }
-                DPRINTF(2, "Unsupported opcode %s\n", uop_name(opcode));
+                DPRINTF(2, "Unsupported opcode %s\n", _PyUopName(opcode));
                 OPT_UNSUPPORTED_OPCODE(opcode);
                 goto done;  // Break out of loop
             }  // End default
@@ -844,7 +844,7 @@ make_executor_from_uops(_PyUOpInstruction *buffer, _PyBloomFilter *dependencies)
         for (int i = 0; i < length; i++) {
             printf("%4d %s(%d, %d, %" PRIu64 ")\n",
                    i,
-                   uop_name(executor->trace[i].opcode),
+                   _PyUopName(executor->trace[i].opcode),
                    executor->trace[i].oparg,
                    executor->trace[i].target,
                    executor->trace[i].operand);