Repository: python/cpython
Pull request: gh-103615: Use local events for opcode tracing
The opcode tracing of PEP 669 to support legacy tracing is not ideal. I talked about it in #103615 but I'll list the gist here:
1. The user has to set `f_trace_opcodes` BEFORE `sys.settrace()`, which is different than what it used to do (I'd consider this as a bug actually).
2. Once `f_trace_opcodes` is set once, you set it globally and forever. The instruction event callback will ALWAYS trigger on every single instruction when you are tracing, even if `f_trace_opcodes` is set to `False` on that frame. It will stick even if you turn off the trace and back on. (there will be no event because in the callback, `f_trace_opcodes` is explicitly checked, but it's a performance hit).

The best way to fix this is to use local events for opcode tracing. By nature, opcode tracing is enabled frame by frame, there's no way to enable it globally for every code object from Python, so that's what the underlying structure should do.

There are 4 occasions to enable instrumentation on instruction event on a code object:
1. when we do `frame.f_trace_opcode = True` if trace is enabled already
2. when we enter a frame on a CALL event - the instruction instrumentation could be stripped because we turned off trace on this frame, but `frame.f_trace_opcode` may persist.
3. when we enable trace with `frame.f_trace_opcode == True`
4. when we set `frame.f_trace = True` - this is to trace the current frame before a call.

There is only 1 case when we need to disable the instrumentation:
1. when the instruction event fires and we realize `f_trace_opcode == False`
2. However, just to make the obvious case, I also added the disabling when we set `f_trace_opcode = False`

With this mechanism, we eliminate the global `f_opcode_trace_set`.

<details>
<summary>
The performance improvement is significant on cases when opcode events is only needed from a small piece of code:
</summary>

```python
import sys
import time

def g():
    a = 0
    for _ in range(100000):
        a += 1
    return a

def f():
    for _ in range(10):
        g()

events = 0

def trace(frame, event, arg):
    global events
    if event == 'opcode':
        events += 1
    return trace

frame = sys._getframe()
frame.f_trace_opcodes = True
sys.settrace(trace)
start = time.time()
f()
print(time.time() - start)
sys.settrace(None)
print(events)
```

For the code above, the time saving is about 50%.

</details>

Oh, this also fixes #108982.

<!-- gh-issue-number: gh-103615 -->
* Issue: gh-103615
<!-- /gh-issue-number -->


Problem statement:
test_sys_settrace tests are not independent
Running any of TraceOpcodesTestCase tests from test_sys_settrace always fails. For example:
```
$ ./python -m test -v test_sys_settrace -m test.test_sys_settrace.TraceOpcodesTestCase.test_01_basic
...
test_01_basic (test.test_sys_settrace.TraceOpcodesTestCase.test_01_basic) ... FAIL

======================================================================
FAIL: test_01_basic (test.test_sys_settrace.TraceOpcodesTestCase.test_01_basic)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/serhiy/py/cpython/Lib/test/test_sys_settrace.py", line 388, in test_01_basic
    self.run_test(basic)
  File "/home/serhiy/py/cpython/Lib/test/test_sys_settrace.py", line 364, in run_test
    self.run_and_compare(func, func.events)
  File "/home/serhiy/py/cpython/Lib/test/test_sys_settrace.py", line 360, in run_and_compare
    self.compare_events(func.__code__.co_firstlineno,
  File "/home/serhiy/py/cpython/Lib/test/test_sys_settrace.py", line 1745, in compare_events
    self.assertLess(len(skip_opcode_events), len(events),
AssertionError: 3 not less than 3 : No 'opcode' events received by the tracer
...
```

Running several of TraceOpcodesTestCase tests only fails the first of them.

Running also `RaisingTraceFuncTestCase.test_line_event_raises_before_opcode_event` makes the tests passing successfully.
```
$ ./python -m test -v test_sys_settrace -m test.test_sys_settrace.TraceOpcodesTestCase.test_01_basic -m test_line_event_raises_before_opcode_event
...
test_line_event_raises_before_opcode_event (test.test_sys_settrace.RaisingTraceFuncTestCase.test_line_event_raises_before_opcode_event) ... ok
test_01_basic (test.test_sys_settrace.TraceOpcodesTestCase.test_01_basic) ... ok
...
```

Hints from issue discussion:
It is only reproduced in 3.12+.
This is a known issue #103615. I have not had the chance to fix it. The issue is that you can't start the trace before you set `trace_opcode = True`. It's an underlying tracing mechanism problem that requires some architecture change.
Is there a workaround for tests which does not invalidate the purposes of tests?

#103615 did not mention test_sys_settrace. Should we close this issue or keep it until #103615 be solved to ensure that this issue also is fixed?
I can do a hacky workaround if that's what needed for now - basically we just need to ensure `f_trace_opcodes` is set to `True` at least once on ANY frame before we start tracing. It that helps the validation, I can do the PR - it's pretty trivial. We should, however, remove it when it's not needed.

#108976 is not fixed after the workaround though. It has a deeper issue.

Commit message: Merge branch 'main' into pep669-opcode-trace

Patch to review:
diff --git a/Include/internal/pycore_ceval.h b/Include/internal/pycore_ceval.h
index 312d67ee0b37aa..8bafe081bfc766 100644
--- a/Include/internal/pycore_ceval.h
+++ b/Include/internal/pycore_ceval.h
@@ -20,6 +20,8 @@ PyAPI_FUNC(int) _PyEval_SetProfile(PyThreadState *tstate, Py_tracefunc func, PyO
 
 extern int _PyEval_SetTrace(PyThreadState *tstate, Py_tracefunc func, PyObject *arg);
 
+extern int _PyEval_SetOpcodeTrace(PyFrameObject *f, bool enable);
+
 // Helper to look up a builtin object
 // Export for 'array' shared extension
 PyAPI_FUNC(PyObject*) _PyEval_GetBuiltin(PyObject *);
diff --git a/Include/internal/pycore_instruments.h b/Include/internal/pycore_instruments.h
index 97dcfb9f8672f7..eae8371ef7f9b8 100644
--- a/Include/internal/pycore_instruments.h
+++ b/Include/internal/pycore_instruments.h
@@ -63,6 +63,8 @@ typedef uint32_t _PyMonitoringEventSet;
 PyObject *_PyMonitoring_RegisterCallback(int tool_id, int event_id, PyObject *obj);
 
 int _PyMonitoring_SetEvents(int tool_id, _PyMonitoringEventSet events);
+int _PyMonitoring_SetLocalEvents(PyCodeObject *code, int tool_id, _PyMonitoringEventSet events);
+int _PyMonitoring_GetLocalEvents(PyCodeObject *code, int tool_id, _PyMonitoringEventSet *events);
 
 extern int
 _Py_call_instrumentation(PyThreadState *tstate, int event,
diff --git a/Include/internal/pycore_interp.h b/Include/internal/pycore_interp.h
index 80f16af54457fb..efc1a48a53c8fa 100644
--- a/Include/internal/pycore_interp.h
+++ b/Include/internal/pycore_interp.h
@@ -220,7 +220,6 @@ struct _is {
     uint32_t next_func_version;
 
     _Py_GlobalMonitors monitors;
-    bool f_opcode_trace_set;
     bool sys_profile_initialized;
     bool sys_trace_initialized;
     Py_ssize_t sys_profiling_threads; /* Count of threads with c_profilefunc set */
diff --git a/Lib/test/test_sys_settrace.py b/Lib/test/test_sys_settrace.py
index f02169602e4925..ce042979abb262 100644
--- a/Lib/test/test_sys_settrace.py
+++ b/Lib/test/test_sys_settrace.py
@@ -9,6 +9,10 @@
 import asyncio
 from test.support import import_helper
 import contextlib
+import os
+import tempfile
+import textwrap
+import subprocess
 
 support.requires_working_socket(module=True)
 
@@ -1801,6 +1805,39 @@ def compare_events(self, line_offset, events, expected_events):
     def make_tracer():
         return Tracer(trace_opcode_events=True)
 
+    def test_trace_opcodes_after_settrace(self):
+        """Make sure setting f_trace_opcodes after starting trace works even
+        if it's the first time f_trace_opcodes is being set. GH-103615"""
+
+        code = textwrap.dedent("""
+            import sys
+
+            def opcode_trace_func(frame, event, arg):
+                if event == "opcode":
+                    print("opcode trace triggered")
+                return opcode_trace_func
+
+            sys.settrace(opcode_trace_func)
+            sys._getframe().f_trace = opcode_trace_func
+            sys._getframe().f_trace_opcodes = True
+            a = 1
+        """)
+
+        # We can't use context manager because Windows can't execute a file while
+        # it's being written
+        tmp = tempfile.NamedTemporaryFile(delete=False, suffix='.py')
+        tmp.write(code.encode('utf-8'))
+        tmp.close()
+        try:
+            p = subprocess.Popen([sys.executable, tmp.name], stdout=subprocess.PIPE, stderr=subprocess.PIPE)
+            p.wait()
+            out = p.stdout.read()
+        finally:
+            os.remove(tmp.name)
+            p.stdout.close()
+            p.stderr.close()
+        self.assertIn(b"opcode trace triggered", out)
+
 
 class RaisingTraceFuncTestCase(unittest.TestCase):
     def setUp(self):
diff --git a/Misc/NEWS.d/next/Core and Builtins/2023-09-15-23-39-43.gh-issue-103615.WZavly.rst b/Misc/NEWS.d/next/Core and Builtins/2023-09-15-23-39-43.gh-issue-103615.WZavly.rst
new file mode 100644
index 00000000000000..2a0e10b84ccf32
--- /dev/null
+++ b/Misc/NEWS.d/next/Core and Builtins/2023-09-15-23-39-43.gh-issue-103615.WZavly.rst	
@@ -0,0 +1 @@
+Use local events for opcode tracing
diff --git a/Objects/frameobject.c b/Objects/frameobject.c
index d75444393f3697..c1f0ede1b23786 100644
--- a/Objects/frameobject.c
+++ b/Objects/frameobject.c
@@ -127,10 +127,13 @@ frame_settrace_opcodes(PyFrameObject *f, PyObject* value, void *Py_UNUSED(ignore
     }
     if (value == Py_True) {
         f->f_trace_opcodes = 1;
-        _PyInterpreterState_GET()->f_opcode_trace_set = true;
+        if (f->f_trace) {
+            return _PyEval_SetOpcodeTrace(f, true);
+        }
     }
     else {
         f->f_trace_opcodes = 0;
+        return _PyEval_SetOpcodeTrace(f, false);
     }
     return 0;
 }
@@ -840,6 +843,9 @@ frame_settrace(PyFrameObject *f, PyObject* v, void *closure)
     }
     if (v != f->f_trace) {
         Py_XSETREF(f->f_trace, Py_XNewRef(v));
+        if (v != NULL && f->f_trace_opcodes) {
+            return _PyEval_SetOpcodeTrace(f, true);
+        }
     }
     return 0;
 }
diff --git a/Python/instrumentation.c b/Python/instrumentation.c
index eee1908e503e43..0de57456c764c6 100644
--- a/Python/instrumentation.c
+++ b/Python/instrumentation.c
@@ -1838,6 +1838,23 @@ _PyMonitoring_SetLocalEvents(PyCodeObject *code, int tool_id, _PyMonitoringEvent
     return 0;
 }
 
+int
+_PyMonitoring_GetLocalEvents(PyCodeObject *code, int tool_id, _PyMonitoringEventSet *events)
+{
+    assert(0 <= tool_id && tool_id < PY_MONITORING_TOOL_IDS);
+    PyInterpreterState *interp = _PyInterpreterState_GET();
+    if (check_tool(interp, tool_id)) {
+        return -1;
+    }
+    if (code->_co_monitoring == NULL) {
+        *events = 0;
+        return 0;
+    }
+    _Py_LocalMonitors *local = &code->_co_monitoring->local_monitors;
+    *events = get_local_events(local, tool_id);
+    return 0;
+}
+
 /*[clinic input]
 module monitoring
 [clinic start generated code]*/
diff --git a/Python/legacy_tracing.c b/Python/legacy_tracing.c
index 97d39a14ae43d0..a221726a9d5e8e 100644
--- a/Python/legacy_tracing.c
+++ b/Python/legacy_tracing.c
@@ -107,6 +107,33 @@ sys_profile_call_or_return(
     Py_RETURN_NONE;
 }
 
+int
+_PyEval_SetOpcodeTrace(
+    PyFrameObject *frame,
+    bool enable
+) {
+    assert(frame != NULL);
+    assert(PyCode_Check(frame->f_frame->f_executable));
+
+    PyCodeObject *code = (PyCodeObject *)frame->f_frame->f_executable;
+    _PyMonitoringEventSet events = 0;
+    if (_PyMonitoring_GetLocalEvents(code, PY_MONITORING_SYS_TRACE_ID, &events) == 0) {
+        if (enable) {
+            if (events & (1 << PY_MONITORING_EVENT_INSTRUCTION)) {
+                return 0;
+            }
+            events |= (1 << PY_MONITORING_EVENT_INSTRUCTION);
+        } else {
+            if (!(events & (1 << PY_MONITORING_EVENT_INSTRUCTION))) {
+                return 0;
+            }
+            events &= (~(1 << PY_MONITORING_EVENT_INSTRUCTION));
+        }
+        return _PyMonitoring_SetLocalEvents(code, PY_MONITORING_SYS_TRACE_ID, events);
+    }
+    return -1;
+}
+
 static PyObject *
 call_trace_func(_PyLegacyEventHandler *self, PyObject *arg)
 {
@@ -120,6 +147,12 @@ call_trace_func(_PyLegacyEventHandler *self, PyObject *arg)
                         "Missing frame when calling trace function.");
         return NULL;
     }
+    if (frame->f_trace_opcodes) {
+        if (_PyEval_SetOpcodeTrace(frame, true) != 0) {
+            return NULL;
+        }
+    }
+
     Py_INCREF(frame);
     int err = tstate->c_tracefunc(tstate->c_traceobj, frame, self->event, arg);
     Py_DECREF(frame);
@@ -210,11 +243,14 @@ sys_trace_instruction_func(
                         "Missing frame when calling trace function.");
         return NULL;
     }
-    if (!frame->f_trace_opcodes) {
+    PyThreadState *tstate = _PyThreadState_GET();
+    if (!tstate->c_tracefunc || !frame->f_trace_opcodes) {
+        if (_PyEval_SetOpcodeTrace(frame, false) != 0) {
+            return NULL;
+        }
         Py_RETURN_NONE;
     }
     Py_INCREF(frame);
-    PyThreadState *tstate = _PyThreadState_GET();
     int err = tstate->c_tracefunc(tstate->c_traceobj, frame, self->event, Py_None);
     frame->f_lineno = 0;
     Py_DECREF(frame);
@@ -511,9 +547,15 @@ _PyEval_SetTrace(PyThreadState *tstate, Py_tracefunc func, PyObject *arg)
             (1 << PY_MONITORING_EVENT_PY_UNWIND) | (1 << PY_MONITORING_EVENT_PY_THROW) |
             (1 << PY_MONITORING_EVENT_STOP_ITERATION) |
             (1 << PY_MONITORING_EVENT_EXCEPTION_HANDLED);
-        if (tstate->interp->f_opcode_trace_set) {
-            events |= (1 << PY_MONITORING_EVENT_INSTRUCTION);
+
+        PyFrameObject* frame = PyEval_GetFrame();
+        if (frame->f_trace_opcodes) {
+            int ret = _PyEval_SetOpcodeTrace(frame, true);
+            if (ret != 0) {
+                return ret;
+            }
         }
     }
+
     return _PyMonitoring_SetEvents(PY_MONITORING_SYS_TRACE_ID, events);
 }
diff --git a/Python/pystate.c b/Python/pystate.c
index 92cf741f4ca4ed..9c3b1a6de1b259 100644
--- a/Python/pystate.c
+++ b/Python/pystate.c
@@ -717,7 +717,6 @@ init_interpreter(PyInterpreterState *interp,
         /* Fix the self-referential, statically initialized fields. */
         interp->dtoa = (struct _dtoa_state)_dtoa_state_INIT(interp);
     }
-    interp->f_opcode_trace_set = false;
 
     assert(runtime->xidregistry.mutex != NULL);
     interp->xidregistry.mutex = runtime->xidregistry.mutex;
@@ -974,7 +973,6 @@ interpreter_clear(PyInterpreterState *interp, PyThreadState *tstate)
         interp->code_watchers[i] = NULL;
     }
     interp->active_code_watchers = 0;
-    interp->f_opcode_trace_set = false;
     // XXX Once we have one allocator per interpreter (i.e.
     // per-interpreter GC) we must ensure that all of the interpreter's
     // objects have been cleaned up at the point.


Code review comments:
diff_hunk: @@ -107,6 +107,33 @@ sys_profile_call_or_return(
     Py_RETURN_NONE;
 }
 
+int
+_PyEval_SetOpcodeTrace(
+    PyFrameObject *frame,
+    bool enable
+) {
+    assert(frame != NULL);
+    assert(PyCode_Check(frame->f_frame->f_executable));
+
+    PyCodeObject *code = (PyCodeObject *)frame->f_frame->f_executable;
+    _PyMonitoringEventSet events = 0;
+    if (_PyMonitoring_GetLocalEvents(code, PY_MONITORING_SYS_TRACE_ID, &events) == 0) {
path: Python/legacy_tracing.c
text: @user1:
Minor style issue.
We generally check for errors, not success, so we can early exit.
```C
   if (_PyMonitoring_GetLocalEvents(code, PY_MONITORING_SYS_TRACE_ID, &events) < 0) {
        return -1;
   }
   /* Rest of code goes here */
```


@author:
Fixed, thanks!