From 76d086890790f1bfbe05d12e02cadb539db5b0b1 Mon Sep 17 00:00:00 2001 From: Guido van Rossum Date: Mon, 18 Mar 2024 11:08:43 -0700 Subject: Cleanup tier2 debug output (#116920) Various tweaks, including a slight refactor of the special cases for `_PUSH_FRAME`/`_POP_FRAME` to show the actual operand emitted. --- Python/ceval.c | 9 +++++++-- Python/optimizer.c | 43 +++++++++++++++++++++++++++---------------- Python/optimizer_analysis.c | 18 ++++++++++++++---- Python/optimizer_bytecodes.c | 1 + Python/optimizer_cases.c.h | 1 + 5 files changed, 50 insertions(+), 22 deletions(-) diff --git a/Python/ceval.c b/Python/ceval.c index f817f28..9dbcd3d 100644 --- a/Python/ceval.c +++ b/Python/ceval.c @@ -1017,7 +1017,12 @@ enter_tier_two: uopcode = next_uop->opcode; #ifdef Py_DEBUG if (lltrace >= 3) { - printf("%4d uop: ", (int)(next_uop - (current_executor == NULL ? next_uop : current_executor->trace))); + if (next_uop->opcode == _START_EXECUTOR || next_uop->opcode == _COLD_EXIT) { + printf("%4d uop: ", 0); + } + else { + printf("%4d uop: ", (int)(next_uop - current_executor->trace)); + } _PyUOpPrint(next_uop); printf(" stack_level=%d\n", (int)(stack_pointer - _PyFrame_Stackbase(frame))); @@ -1113,7 +1118,7 @@ side_exit: _PyUOpPrint(&next_uop[-1]); printf(", exit %u, temp %d, target %d -> %s]\n", exit_index, exit->temperature, exit->target, - _PyOpcode_OpName[frame->instr_ptr->op.code]); + _PyOpcode_OpName[_PyCode_CODE(_PyFrame_GetCode(frame))[exit->target].op.code]); } #endif Py_INCREF(exit->executor); diff --git a/Python/optimizer.c b/Python/optimizer.c index 88c45f2..a6d6ffe 100644 --- a/Python/optimizer.c +++ b/Python/optimizer.c @@ -313,7 +313,7 @@ _PyUOpPrint(const _PyUOpInstruction *uop) else { printf("%s", name); } - printf(" (%d, target=%d, operand=%" PRIx64 ")", + printf(" (%d, target=%d, operand=%#" PRIx64 ")", uop->oparg, uop->target, (uint64_t)uop->operand); @@ -528,7 +528,7 @@ translate_bytecode_to_trace( } #endif - DPRINTF(4, + DPRINTF(2, "Optimizing %s (%s:%d) at byte offset %d\n", PyUnicode_AsUTF8(code->co_qualname), PyUnicode_AsUTF8(code->co_filename), @@ -546,7 +546,7 @@ top: // Jump here after _PUSH_FRAME or likely branches uint32_t oparg = instr->op.arg; uint32_t extended = 0; - DPRINTF(3, "%d: %s(%d)\n", target, _PyOpcode_OpName[opcode], oparg); + DPRINTF(2, "%d: %s(%d)\n", target, _PyOpcode_OpName[opcode], oparg); if (opcode == ENTER_EXECUTOR) { assert(oparg < 256); @@ -606,7 +606,7 @@ top: // Jump here after _PUSH_FRAME or likely branches confidence = confidence * (18 - bitcount) / 20; } uint32_t uopcode = BRANCH_TO_GUARD[opcode - POP_JUMP_IF_FALSE][jump_likely]; - DPRINTF(2, "%d: %s(%d): counter=%x, bitcount=%d, likely=%d, confidence=%d, uopcode=%s\n", + DPRINTF(2, "%d: %s(%d): counter=%04x, bitcount=%d, likely=%d, confidence=%d, uopcode=%s\n", target, _PyOpcode_OpName[opcode], oparg, counter, bitcount, jump_likely, confidence, _PyUOpName(uopcode)); if (confidence < CONFIDENCE_CUTOFF) { @@ -617,7 +617,7 @@ top: // Jump here after _PUSH_FRAME or likely branches _Py_CODEUNIT *next_instr = instr + 1 + _PyOpcode_Caches[_PyOpcode_Deopt[opcode]]; _Py_CODEUNIT *target_instr = next_instr + oparg; if (jump_likely) { - DPRINTF(2, "Jump likely (%x = %d bits), continue at byte offset %d\n", + DPRINTF(2, "Jump likely (%04x = %d bits), continue at byte offset %d\n", instr[1].cache, bitcount, 2 * INSTR_IP(target_instr, code)); instr = target_instr; ADD_TO_TRACE(uopcode, max_length, 0, INSTR_IP(next_instr, code)); @@ -716,12 +716,12 @@ top: // Jump here after _PUSH_FRAME or likely branches expansion->uops[i].offset); Py_FatalError("garbled expansion"); } - ADD_TO_TRACE(uop, oparg, operand, target); + if (uop == _POP_FRAME) { TRACE_STACK_POP(); /* Set the operand to the function object returned to, * to assist optimization passes */ - trace[trace_length-1].operand = (uintptr_t)func; + ADD_TO_TRACE(uop, oparg, (uintptr_t)func, target); DPRINTF(2, "Returning to %s (%s:%d) at byte offset %d\n", PyUnicode_AsUTF8(code->co_qualname), @@ -730,6 +730,7 @@ top: // Jump here after _PUSH_FRAME or likely branches 2 * INSTR_IP(instr, code)); goto top; } + if (uop == _PUSH_FRAME) { assert(i + 1 == nuops); int func_version_offset = @@ -738,7 +739,7 @@ top: // Jump here after _PUSH_FRAME or likely branches + 1; uint32_t func_version = read_u32(&instr[func_version_offset].cache); PyFunctionObject *new_func = _PyFunction_LookupByVersion(func_version); - DPRINTF(3, "Function object: %p\n", func); + DPRINTF(2, "Function: version=%#x; object=%p\n", (int)func_version, new_func); if (new_func != NULL) { PyCodeObject *new_code = (PyCodeObject *)PyFunction_GET_CODE(new_func); if (new_code == code) { @@ -748,6 +749,7 @@ top: // Jump here after _PUSH_FRAME or likely branches PyUnicode_AsUTF8(new_code->co_filename), new_code->co_firstlineno); OPT_STAT_INC(recursive_call); + ADD_TO_TRACE(uop, oparg, 0, target); ADD_TO_TRACE(_EXIT_TRACE, 0, 0, 0); goto done; } @@ -756,6 +758,7 @@ top: // Jump here after _PUSH_FRAME or likely branches // Perhaps it may happen again, so don't bother tracing. // TODO: Reason about this -- is it better to bail or not? DPRINTF(2, "Bailing because co_version != func_version\n"); + ADD_TO_TRACE(uop, oparg, 0, target); ADD_TO_TRACE(_EXIT_TRACE, 0, 0, 0); goto done; } @@ -763,9 +766,9 @@ top: // Jump here after _PUSH_FRAME or likely branches instr += _PyOpcode_Caches[_PyOpcode_Deopt[opcode]] + 1; TRACE_STACK_PUSH(); _Py_BloomFilter_Add(dependencies, new_code); - /* Set the operand to the callee's code object, - * to assist optimization passes */ - trace[trace_length-1].operand = (uintptr_t)new_func; + /* Set the operand to the callee's function object, + * to assist optimization passes */ + ADD_TO_TRACE(uop, oparg, (uintptr_t)new_func, target); code = new_code; func = new_func; instr = _PyCode_CODE(code); @@ -777,9 +780,14 @@ top: // Jump here after _PUSH_FRAME or likely branches 2 * INSTR_IP(instr, code)); goto top; } + DPRINTF(2, "Bail, new_func == NULL\n"); + ADD_TO_TRACE(uop, oparg, operand, target); ADD_TO_TRACE(_EXIT_TRACE, 0, 0, 0); goto done; } + + // All other instructions + ADD_TO_TRACE(uop, oparg, operand, target); } break; } @@ -803,17 +811,18 @@ done: // Skip short traces like _SET_IP, LOAD_FAST, _SET_IP, _EXIT_TRACE if (progress_needed || trace_length < 5) { OPT_STAT_INC(trace_too_short); - DPRINTF(4, - "No trace for %s (%s:%d) at byte offset %d\n", + DPRINTF(2, + "No trace for %s (%s:%d) at byte offset %d (%s)\n", PyUnicode_AsUTF8(code->co_qualname), PyUnicode_AsUTF8(code->co_filename), code->co_firstlineno, - 2 * INSTR_IP(initial_instr, code)); + 2 * INSTR_IP(initial_instr, code), + progress_needed ? "no progress" : "too short"); return 0; } ADD_TO_TRACE(_EXIT_TRACE, 0, 0, target); DPRINTF(1, - "Created a trace for %s (%s:%d) at byte offset %d -- length %d\n", + "Created a proto-trace for %s (%s:%d) at byte offset %d -- length %d\n", PyUnicode_AsUTF8(code->co_qualname), PyUnicode_AsUTF8(code->co_filename), code->co_firstlineno, @@ -938,6 +947,8 @@ make_executor_from_uops(_PyUOpInstruction *buffer, const _PyBloomFilter *depende assert(next_exit == -1); assert(dest == executor->trace); dest->opcode = _START_EXECUTOR; + dest->oparg = 0; + dest->target = 0; dest->operand = (uintptr_t)executor; _Py_ExecutorInit(executor, dependencies); #ifdef Py_DEBUG @@ -947,7 +958,7 @@ make_executor_from_uops(_PyUOpInstruction *buffer, const _PyBloomFilter *depende lltrace = *python_lltrace - '0'; // TODO: Parse an int and all that } if (lltrace >= 2) { - printf("Optimized executor (length %d):\n", length); + printf("Optimized trace (length %d):\n", length); for (int i = 0; i < length; i++) { printf("%4d OPTIMIZED: ", i); _PyUOpPrint(&executor->trace[i]); diff --git a/Python/optimizer_analysis.c b/Python/optimizer_analysis.c index 9fd4b19..0c95616 100644 --- a/Python/optimizer_analysis.c +++ b/Python/optimizer_analysis.c @@ -35,6 +35,7 @@ #ifdef Py_DEBUG extern const char *_PyUOpName(int index); + extern void _PyUOpPrint(const _PyUOpInstruction *uop); static const char *const DEBUG_ENV = "PYTHON_OPT_DEBUG"; static inline int get_lltrace(void) { char *uop_debug = Py_GETENV(DEBUG_ENV); @@ -377,14 +378,20 @@ optimize_uops( _Py_UopsSymbol **stack_pointer = ctx->frame->stack_pointer; - DPRINTF(3, "Abstract interpreting %s:%d ", - _PyUOpName(opcode), - oparg); +#ifdef Py_DEBUG + if (get_lltrace() >= 3) { + printf("%4d abs: ", (int)(this_instr - trace)); + _PyUOpPrint(this_instr); + printf(" "); + } +#endif + switch (opcode) { + #include "optimizer_cases.c.h" default: - DPRINTF(1, "Unknown opcode in abstract interpreter\n"); + DPRINTF(1, "\nUnknown opcode in abstract interpreter\n"); Py_UNREACHABLE(); } assert(ctx->frame != NULL); @@ -397,11 +404,13 @@ optimize_uops( return 1; out_of_space: + DPRINTF(3, "\n"); DPRINTF(1, "Out of space in abstract interpreter\n"); _Py_uop_abstractcontext_fini(ctx); return 0; error: + DPRINTF(3, "\n"); DPRINTF(1, "Encountered error in abstract interpreter\n"); _Py_uop_abstractcontext_fini(ctx); return 0; @@ -411,6 +420,7 @@ hit_bottom: // This means that the abstract interpreter has hit unreachable code. // We *could* generate an _EXIT_TRACE or _FATAL_ERROR here, but it's // simpler to just admit failure and not create the executor. + DPRINTF(3, "\n"); DPRINTF(1, "Hit bottom in abstract interpreter\n"); _Py_uop_abstractcontext_fini(ctx); return 0; diff --git a/Python/optimizer_bytecodes.c b/Python/optimizer_bytecodes.c index 54abbcd..ef08c0d 100644 --- a/Python/optimizer_bytecodes.c +++ b/Python/optimizer_bytecodes.c @@ -544,6 +544,7 @@ dummy_func(void) { (void)callable; PyFunctionObject *func = (PyFunctionObject *)(this_instr + 2)->operand; + DPRINTF(3, "func: %p ", func); if (func == NULL) { goto error; } diff --git a/Python/optimizer_cases.c.h b/Python/optimizer_cases.c.h index cf36f1b..610d1b1 100644 --- a/Python/optimizer_cases.c.h +++ b/Python/optimizer_cases.c.h @@ -1597,6 +1597,7 @@ int argcount = oparg; (void)callable; PyFunctionObject *func = (PyFunctionObject *)(this_instr + 2)->operand; + DPRINTF(3, "func: %p ", func); if (func == NULL) { goto error; } -- cgit v0.12