From 7405745817d19e13585dd4f0f9b8338ba5b32418 Mon Sep 17 00:00:00 2001 From: Guido van Rossum Date: Fri, 17 Nov 2023 14:25:57 -0800 Subject: [PATCH] Various small improvements to uop debug output (#112218) - Show uop name in Error/DEOPT messages - Add target to some messages - Expose uop_name() as _PyUopName() --- Python/ceval.c | 15 +++++++++++---- Python/optimizer.c | 18 +++++++++--------- 2 files changed, 20 insertions(+), 13 deletions(-) diff --git a/Python/ceval.c b/Python/ceval.c index d684c72cc9e..ae515780440 100644 --- 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 index 5d1ef8a683c..64a15e0dd66 100644 --- 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 = ""; } @@ -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);