8000 gh-91462: Make lltrace output human-readable. (GH-91463) · python/cpython@8560f4a · GitHub
[go: up one dir, main page]
Skip to content

Commit 8560f4a

Browse files
sweeneydesweeneyde
authored
gh-91462: Make lltrace output human-readable. (GH-91463)
* Transform opcodes into opnames * Print the whole stack at each opcode, and eliminate prtrace output at each (push/pop/stackadj) * Display info about the function at each resume_frame
1 parent 25af5ea commit 8560f4a

File tree

3 files changed

+173
-43
lines changed

3 files changed

+173
-43
lines changed

‎Lib/test/test_lltrace.py

Lines changed: 89 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -1,31 +1,112 @@
1-
import os
1+
import dis
2+
import sys
23
import textwrap
34
import unittest
45

5-
from test.support import os_helper
6+
from test.support import os_helper, verbose
67
from test.support.script_helper import assert_python_ok
78

9+
def example():
10+
x = []
11+
for i in range(1):
12+
x.append(i)
13+
x = "this is"
14+
y = "an example"
15+
print(x, y)
816

17+
Py_DEBUG = hasattr(sys, 'gettotalrefcount')
18+
19+
@unittest.skipUnless(Py_DEBUG, "lltrace requires Py_DEBUG")
920
class TestLLTrace(unittest.TestCase):
1021

22+
def run_code(self, code):
23+
code = textwrap.dedent(code).strip()
24+
with open(os_helper.TESTFN, 'w', encoding='utf-8') as fd:
25+
self.addCleanup(os_helper.unlink, os_helper.TESTFN)
26+
fd.write(code)
27+
status, stdout, stderr = assert_python_ok(os_helper.TESTFN)
28+
self.assertEqual(stderr, b"")
29+
self.assertEqual(status, 0)
30+
result = stdout.decode('utf-8')
31+
if verbose:
32+
print("\n\n--- code ---")
33+
print(code)
34+
print("\n--- stdout ---")
35+
print(result)
36+
print()
37+
return result
38+
39+
def test_lltrace(self):
40+
stdout = self.run_code("""
41+
def dont_trace_1():
42+
a = "a"
43+
a = 10 * a
44+
def trace_me():
45+
for i in range(3):
46+
+i
47+
def dont_trace_2():
48+
x = 42
49+
y = -x
50+
dont_trace_1()
51+
__ltrace__ = 1
52+
trace_me()
53+
del __ltrace__
54+
dont_trace_2()
55+
""")
56+
self.assertIn("GET_ITER", stdout)
57+
self.assertIn("FOR_ITER", stdout)
58+
self.assertIn("UNARY_POSITIVE", stdout)
59+
self.assertIn("POP_TOP", stdout)
60+
self.assertNotIn("BINARY_OP", stdout)
61+
self.assertNotIn("UNARY_NEGATIVE", stdout)
62+
63+
self.assertIn("'trace_me' in module '__main__'", stdout)
64+
self.assertNotIn("dont_trace_1", stdout)
65+
self.assertNotIn("'dont_trace_2' in module", stdout)
66+
67+
def test_lltrace_different_module(self):
68+
stdout = self.run_code("""
69+
from test import test_lltrace
70+
test_lltrace.__ltrace__ = 1
71+
test_lltrace.example()
72+
""")
73+
self.assertIn("'example' in module 'test.test_lltrace'", stdout)
74+
self.assertIn('LOAD_CONST', stdout)
75+
self.assertIn('FOR_ITER', stdout)
76+
self.assertIn('this is an example', stdout)
77+
78+
# check that offsets match the output of dis.dis()
79+
instr_map = {i.offset: i for i in dis.get_instructions(example)}
80+
for line in stdout.splitlines():
81+
offset, colon, opname_oparg = line.partition(":")
82+
if not colon:
83+
continue
84+
offset = int(offset)
85+
opname_oparg = opname_oparg.split()
86+
if len(opname_oparg) == 2:
87+
opname, oparg = opname_oparg
88+
oparg = int(oparg)
89+
else:
90+
(opname,) = opname_oparg
91+
oparg = None
92+
self.assertEqual(instr_map[offset].opname, opname)
93+
self.assertEqual(instr_map[offset].arg, oparg)
94+
1195
def test_lltrace_does_not_crash_on_subscript_operator(self):
1296
# If this test fails, it will reproduce a crash reported as
1397
# bpo-34113. The crash happened at the command line console of
1498
# debug Python builds with __ltrace__ enabled (only possible in console),
1599
# when the internal Python stack was negatively adjusted
16-
with open(os_helper.TESTFN, 'w', encoding='utf-8') as fd:
17-
self.addCleanup(os_helper.unlink, os_helper.TESTFN)
18-
fd.write(textwrap.dedent("""\
100+
stdout = self.run_code("""
19101
import code
20102
21103
console = code.InteractiveConsole()
22104
console.push('__ltrace__ = 1')
23105
console.push('a = [1, 2, 3]')
24106
console.push('a[0] = 1')
25107
print('unreachable if bug exists')
26-
"""))
27-
28-
assert_python_ok(os_helper.TESTFN)
108+
""")
109+
self.assertIn("unreachable if bug exists", stdout)
29110

30111
if __name__ == "__main__":
31112
unittest.main()

‎Misc/NEWS.d/next/Core and Builtins/2022-04-12-00-44-14.gh-issue-91462.t8oxyd.rst

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1 @@
1+
Make the interpreter's low-level tracing (lltrace) feature output more readable by displaying opcode names (rather than just numbers), and by displaying stack contents before each opcode.

‎Python/ceval.c

Lines changed: 83 additions & 35 deletions
Original file line numberDiff line numberDiff line change
@@ -54,15 +54,77 @@ static PyObject * do_call_core(
5454

5555
#ifdef LLTRACE
5656
static int lltrace;
57-
static int prtrace(PyThreadState *, PyObject *, const char *);
58-
static void lltrace_instruction(_PyInterpreterFrame *frame, int opcode, int oparg)
57+
static void
58+
dump_stack(_PyInterpreterFrame *frame, PyObject **stack_pointer)
59+
{
60+
PyObject **stack_base = _PyFrame_Stackbase(frame);
61+
PyObject *type, *value, *traceback;
62+
PyErr_Fetch(&type, &value, &traceback);
63+
printf(" stack=[");
64+
for (PyObject **ptr = stack_base; ptr < stack_pointer; ptr++) {
65+
if (ptr != stack_base) {
66+
printf(", ");
67+
}
68+
if (PyObject_Print(*ptr, stdout, 0) != 0) {
69+
PyErr_Clear();
70+
printf("<%s object at %p>",
71+
Py_TYPE(*ptr)->tp_name, (void *)(*ptr));
72+
}
73+
}
74+
printf("]\n");
75+
fflush(stdout);
76+
PyErr_Restore(type, value, traceback);
77+
}
78+
79+
static void
80+
lltrace_instruction(_PyInterpreterFrame *frame,
81+
PyObject **stack_pointer,
82+
_Py_CODEUNIT *next_instr)
5983
{
84+
dump_stack(frame, stack_pointer);
85+
int oparg = _Py_OPARG(*next_instr);
86+
int opcode = _Py_OPCODE(*next_instr);
87+
const char *opname = _PyOpcode_OpName[opcode];
88+
assert(opname != NULL);
89+
int offset = (int)(next_instr - _PyCode_CODE(frame->f_code));
6090
if (HAS_ARG(opcode)) {
61-
printf("%d: %d, %d\n", _PyInterpreterFrame_LASTI(frame), opcode, oparg);
91+
printf("%d: %s %d\n", offset * 2, opname, oparg);
6292
}
6393
else {
64-
printf("%d: %d\n", _PyInterpreterFrame_LASTI(frame), opcode);
94+
printf("%d: %s\n", offset * 2, opname);
95+
}
96+
fflush(stdout);
97+
}
98+
static void
99+
lltrace_resume_frame(_PyInterpreterFrame *frame)
100+
{
101+
PyFunctionObject *f = frame->f_func;
102+
if (f == NULL) {
103+
printf("\nResuming frame.");
104+
return;
105+
}
106+
PyObject *type, *value, *traceback;
107+
PyErr_Fetch(&type, &value, &traceback);
108+
PyObject *name = f->func_qualname;
109+
if (name == NULL) {
110+
name = f->func_name;
111+
}
112+
printf("\nResuming frame");
113+
if (name) {
114+
printf(" for ");
115+
if (PyObject_Print(name, stdout, 0) < 0) {
116+
PyErr_Clear();
117+
}
65118
}
119+
if (f->func_module) {
120+
printf(" in module ");
121+
if (PyObject_Print(f->func_module, stdout, 0) < 0) {
122+
PyErr_Clear();
123+
}
124+
}
125+
printf("\n");
126+
fflush(stdout);
127+
PyErr_Restore(type, value, traceback);
66128
}
67129
#endif
68130
static int call_trace(Py_tracefunc, PyObject *,
@@ -1266,7 +1328,8 @@ eval_frame_handle_pending(PyThreadState *tstate)
12661328

12671329
/* PRE_DISPATCH_GOTO() does lltrace if enabled. Normally a no-op */
12681330
#ifdef LLTRACE
1269-
#define PRE_DISPATCH_GOTO() if (lltrace) { lltrace_instruction(frame, opcode, oparg); }
1331+
#define PRE_DISPATCH_GOTO() if (lltrace) { \
1332+
lltrace_instruction(frame, stack_pointer, next_instr); }
12701333
#else
12711334
#define PRE_DISPATCH_GOTO() ((void)0)
12721335
#endif
@@ -1375,6 +1438,7 @@ eval_frame_handle_pending(PyThreadState *tstate)
13751438
/* The stack can grow at most MAXINT deep, as co_nlocals and
13761439
co_stacksize are ints. */
13771440
#define STACK_LEVEL() ((int)(stack_pointer - _PyFrame_Stackbase(frame)))
1441+
#define STACK_SIZE() (frame->f_code->co_stacksize)
13781442
#define EMPTY() (STACK_LEVEL() == 0)
13791443
#define TOP() (stack_pointer[-1])
13801444
#define SECOND() (stack_pointer[-2])
@@ -1387,23 +1451,21 @@ eval_frame_handle_pending(PyThreadState *tstate)
13871451
#define BASIC_PUSH(v) (*stack_pointer++ = (v))
13881452
#define BASIC_POP() (*--stack_pointer)
13891453

1390-
#ifdef LLTRACE
1391-
#define PUSH(v) { (void)(BASIC_PUSH(v), \
1392-
lltrace && prtrace(tstate, TOP(), "push")); \
1393-
assert(STACK_LEVEL() <= frame->f_code->co_stacksize); }
1394-
#define POP() ((void)(lltrace && prtrace(tstate, TOP(), "pop")), \
1395-
BASIC_POP())
1454+
#ifdef Py_DEBUG
1455+
#define PUSH(v) do { \
1456+
BASIC_PUSH(v); \
1457+
assert(STACK_LEVEL() <= STACK_SIZE()); \
1458+
} while (0)
1459+
#define POP() (assert(STACK_LEVEL() > 0), BASIC_POP())
13961460
#define STACK_GROW(n) do { \
1397-
assert(n >= 0); \
1398-
(void)(BASIC_STACKADJ(n), \
1399-
lltrace && prtrace(tstate, TOP(), "stackadj")); \
1400-
assert(STACK_LEVEL() <= frame->f_code->co_stacksize); \
1461+
assert(n >= 0); \
1462+
BASIC_STACKADJ(n); \
1463+
assert(STACK_LEVEL() <= STACK_SIZE()); \
14011464
} while (0)
14021465
#define STACK_SHRINK(n) do { \
14031466
assert(n >= 0); \
1404-
(void)(lltrace && prtrace(tstate, TOP(), "stackadj")); \
1405-
(void)(BASIC_STACKADJ(-(n))); \
1406-
assert(STACK_LEVEL() <= frame->f_code->co_stacksize); \
1467+
assert(STACK_LEVEL() >= n); \
1468+
BASIC_STACKADJ(-(n)); \
14071469
} while (0)
14081470
#else
14091471
#define PUSH(v) BASIC_PUSH(v)
@@ -1673,6 +1735,9 @@ _PyEval_EvalFrameDefault(PyThreadState *tstate, _PyInterpreterFrame *frame, int
16731735
}
16741736
lltrace = r;
16751737
}
1738+
if (lltrace) {
1739+
lltrace_resume_frame(frame);
1740+
}
16761741
#endif
16771742

16781743
#ifdef Py_DEBUG
@@ -6663,23 +6728,6 @@ unpack_iterable(PyThreadState *tstate, PyObject *v,
66636728
return 0;
66646729
}
66656730

6666-
#ifdef LLTRACE
6667-
static int
6668-
prtrace(PyThreadState *tstate, PyObject *v, const char *str)
6669-
{
6670-
printf("%s ", str);
6671-
PyObject *type, *value, *traceback;
6672-
PyErr_Fetch(&type, &value, &traceback);
6673-
if (PyObject_Print(v, stdout, 0) != 0) {
6674-
/* Don't know what else to do */
6675-
_PyErr_Clear(tstate);
6676-
}
6677-
printf("\n");
6678-
PyErr_Restore(type, value, traceback);
6679-
return 1;
6680-
}
6681-
#endif
6682-
66836731
static void
66846732
call_exc_trace(Py_tracefunc func, PyObject *self,
66856733
PyThreadState *tstate,

0 commit comments

Comments
 (0)
0