Ref tests failure on test_monitoring

[sunmy2019]

Tested on cef542c, GCC 11.3 Ubuntu 22.04

./python -m test test_monitoring -R : 

Error Log

======================================================================
FAIL: test_c_call (test.test_monitoring.TestLineAndInstructionEvents.test_c_call)
----------------------------------------------------------------------
Lists differ:

First differing element 1:
('instruction', 'func2', 2)
('line', 'func2', 1)

Second list contains 3 additional elements.
First extra element 12:
('instruction', 'func2', 42)

  [('line', 'check_events', 10),
+  ('line', 'func2', 1),
   ('instruction', 'func2', 2),
   ('instruction', 'func2', 4),
+  ('line', 'func2', 2),
   ('instruction', 'func2', 6),
   ('instruction', 'func2', 8),
   ('instruction', 'func2', 28),
   ('instruction', 'func2', 30),
   ('instruction', 'func2', 38),
+  ('line', 'func2', 3),
   ('instruction', 'func2', 40),
   ('instruction', 'func2', 42),
   ('instruction', 'func2', 44),
   ('line', 'check_events', 11)]

======================================================================
FAIL: test_simple (test.test_monitoring.TestLineAndInstructionEvents.test_simple)
----------------------------------------------------------------------
Lists differ:

First differing element 1:
('instruction', 'func1', 2)
('line', 'func1', 1)

Second list contains 3 additional elements.
First extra element 9:
('instruction', 'func1', 12)

  [('line', 'check_events', 10),
+  ('line', 'func1', 1),
   ('instruction', 'func1', 2),
   ('instruction', 'func1', 4),
+  ('line', 'func1', 2),
   ('instruction', 'func1', 6),
   ('instruction', 'func1', 8),
+  ('line', 'func1', 3),
   ('instruction', 'func1', 10),
   ('instruction', 'func1', 12),
   ('instruction', 'func1', 14),
   ('line', 'check_events', 11)]

======================================================================
FAIL: test_try_except (test.test_monitoring.TestLineAndInstructionEvents.test_try_except)
----------------------------------------------------------------------
Lists differ:

First differing element 1:
('instruction', 'func3', 2)
('line', 'func3', 1)

Second list contains 6 additional elements.
First extra element 15:
('instruction', 'func3', 28)

  [('line', 'check_events', 10),
+  ('line', 'func3', 1),
   ('instruction', 'func3', 2),
+  ('line', 'func3', 2),
   ('instruction', 'func3', 4),
   ('instruction', 'func3', 6),
+  ('line', 'func3', 3),
   ('instruction', 'func3', 8),
   ('instruction', 'func3', 18),
   ('instruction', 'func3', 20),
+  ('line', 'func3', 4),
   ('instruction', 'func3', 22),
+  ('line', 'func3', 5),
   ('instruction', 'func3', 24),
   ('instruction', 'func3', 26),
   ('instruction', 'func3', 28),
+  ('line', 'func3', 6),
   ('instruction', 'func3', 30),
   ('instruction', 'func3', 32),
   ('instruction', 'func3', 34),
   ('line', 'check_events', 11)]

----------------------------------------------------------------------
Ran 42 tests in 0.015s

FAILED (failures=3)

Looks like the behavior is changed when using -R :?

CC: @markshannon

Linked PRs

• gh-103845: Remove line & instruction instrumentations before adding them back #103851

[gaogaotiantian]

The direct trigger here is sys.monitoring.restart_events(). ./python -m test test_monitoring -R : effectively executes the test suite twice, so there's a sys.monitoring.restart_events() call between two executions of the failed test. Here's a smaller demo:

Demo

import sys

def f():
    def func():
        a = 1
        b = 2

    E = sys.monitoring.events

    TOOL_ID = 2
    sys.monitoring.use_tool_id(TOOL_ID, "test")

    sys.monitoring.register_callback(TOOL_ID, E.LINE, lambda *args: print(args))
    sys.monitoring.register_callback(TOOL_ID, E.INSTRUCTION, lambda *args: print(args))


    sys.monitoring.set_events(TOOL_ID, E.LINE | E.INSTRUCTION)
    func()
    sys.monitoring.set_events(TOOL_ID, 0)

    sys.monitoring.restart_events()
    sys.monitoring.set_events(TOOL_ID, E.LINE | E.INSTRUCTION)
    func()
    sys.monitoring.set_events(TOOL_ID, 0)

f()

When sys.monitoring.restart_events() is called, the monitoring tools are labeled so each code object could be updated. However, in _Py_Instrument(), we are doing separate loops for line & instruction events. So if we restart with both line and instruction events active on the code object we would have:

1. Remove line instrumentation
2. Add line instrumentation
3. Remove instruction instrumentation(!! line instrumentation is removed here !!)
4. Add instruction instrumentation

So the line instrumentations on the code object will be removed and no line event will be generated. This could be confirmed with dis.dis(code, adaptive=True) - no INSTRUMENTED_LINE opcode, instead INSTRUMENTED_INSTRUCTION is there.

The fix could be simply to do remove first, then add. I had a prototype in #103851 and it solved the original issue. I also added a regression test.

[markshannon]

Appears to be fixed.
I ran ./python -m test -F test_monitoring
which made it to 2000 repetitions before I killed it.

@sunmy2019 can you confirm?

[sunmy2019]

Confirmed and closed