Ref tests failure on test_monitoring

@markshannon

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

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:

Remove line instrumentation
Add line instrumentation
Remove instruction instrumentation(!! line instrumentation is removed here !!)
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.

Merge branch 'main' into pythongh-103845

gh-103845: Remove line & instruction instrumentations before adding t…

@sunmy2019

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?

Confirmed and closed

Navigation Menu

Repository navigation

Ref tests failure on test_monitoring #103845

Linked PRs

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Ref tests failure on test_monitoring #103845

Description

Linked PRs

Activity

gaogaotiantian commented on Apr 25, 2023

markshannon commented on May 3, 2023

sunmy2019 commented on May 3, 2023

Metadata

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Issue actions