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/optimizer.c | 43 +++++++++++++++++++++++++++---------------- 1 file changed, 27 insertions(+), 16 deletions(-) (limited to 'Python/optimizer.c') diff --git a/Python/optimizer.c b/Python/optimizer.c index 88c45f2e73c..a6d6ffe5378 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]); -- cgit v1.2.3