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()
This commit is contained in:
Guido van Rossum 2023-11-17 14:25:57 -08:00 committed by GitHub
parent be0bd54c6b
commit 7405745817
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
2 changed files with 20 additions and 13 deletions

View file

@ -647,6 +647,8 @@ static const _Py_CODEUNIT _Py_INTERPRETER_TRAMPOLINE_INSTRUCTIONS[] = {
extern const struct _PyCode_DEF(8) _Py_InitCleanup; extern const struct _PyCode_DEF(8) _Py_InitCleanup;
extern const char *_PyUopName(int index);
/* Disable unused label warnings. They are handy for debugging, even /* Disable unused label warnings. They are handy for debugging, even
if computed gotos aren't used. */ if computed gotos aren't used. */
@ -1002,11 +1004,12 @@ _PyEval_EvalFrameDefault(PyThreadState *tstate, _PyInterpreterFrame *frame, int
oparg = next_uop->oparg; oparg = next_uop->oparg;
operand = next_uop->operand; operand = next_uop->operand;
DPRINTF(3, 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), (int)(next_uop - current_executor->trace),
opcode < 256 ? _PyOpcode_OpName[opcode] : _PyOpcode_uop_name[opcode], _PyUopName(opcode),
oparg, oparg,
operand, operand,
next_uop->target,
(int)(stack_pointer - _PyFrame_Stackbase(frame))); (int)(stack_pointer - _PyFrame_Stackbase(frame)));
next_uop++; next_uop++;
OPT_STAT_INC(uops_executed); OPT_STAT_INC(uops_executed);
@ -1051,7 +1054,9 @@ _PyEval_EvalFrameDefault(PyThreadState *tstate, _PyInterpreterFrame *frame, int
pop_1_error_tier_two: pop_1_error_tier_two:
STACK_SHRINK(1); STACK_SHRINK(1);
error_tier_two: 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); OPT_HIST(trace_uop_execution_counter, trace_run_length_hist);
frame->return_offset = 0; // Don't leave this random frame->return_offset = 0; // Don't leave this random
_PyFrame_SetStackPointer(frame, stack_pointer); _PyFrame_SetStackPointer(frame, stack_pointer);
@ -1062,7 +1067,9 @@ _PyEval_EvalFrameDefault(PyThreadState *tstate, _PyInterpreterFrame *frame, int
deoptimize: deoptimize:
// On DEOPT_IF we just repeat the last instruction. // On DEOPT_IF we just repeat the last instruction.
// This presumes nothing was popped from the stack (nor pushed). // 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); OPT_HIST(trace_uop_execution_counter, trace_run_length_hist);
UOP_STAT_INC(opcode, miss); UOP_STAT_INC(opcode, miss);
frame->return_offset = 0; // Dispatch to frame->instr_ptr frame->return_offset = 0; // Dispatch to frame->instr_ptr

View file

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