Skip to content

gh-103615: Use local events for opcode tracing #109472

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Merged
merged 8 commits into from
Nov 3, 2023
Merged

gh-103615: Use local events for opcode tracing #109472

merged 8 commits into from
Nov 3, 2023

Conversation

gaogaotiantian
Copy link
Member

@gaogaotiantian gaogaotiantian commented Sep 15, 2023 •
edited by bedevere-app bot
Loading

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.

The performance improvement is significant on cases when opcode events is only needed from a small piece of code: 
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%.

Oh, this also fixes #108982.

@bedevere-app bedevere-app bot mentioned this pull request Sep 15, 2023
Closed
@markshannon
Copy link
Member

Looks good.
I like the design, it looks like the performance impact will be low and it definitely looks better than what we have now.

It could do with some tests beyond the implicit one in #108982.
Can you turn #103615 (comment) into a test?

@gaogaotiantian
Copy link
Member Author

Looks good. I like the design, it looks like the performance impact will be low and it definitely looks better than what we have now.

It could do with some tests beyond the implicit one in #108982. Can you turn #103615 (comment) into a test?

The one in #103615 is a bit tricky - it will only reproduce if f_trace_opcode is never set before. I can do it in a separate process and collect the output. Do you think that's worth the effort?

@markshannon
Copy link
Member

markshannon commented Sep 29, 2023 •
edited
Loading

I think it is OK to add as a normal test without using subprocesses.
It is a regression test. It should never fail in the future, it doesn't really matter if it only failed erratically in the past.

Maybe add it to the monitoring tests, rather than sys_settrace tests? That way it will fail if only test.test_monitoring is run.

@gaogaotiantian
Copy link
Member Author

I think it is OK to add as a normal test without using subprocesses. It is a regression test. It should never fail in the future, it doesn't really matter if it only failed erratically in the past.

Maybe add it to the monitoring tests, rather than sys_settrace tests? That way it will fail if only test.test_monitoring is run.

Well if the regression test does not fail on the old code, it does not help that much. If we only run a normal test, then it's doing exactly the same thing as our existing tests for f_trace_opcodes. Putting it in test_monitoring works, but I don't think that's a very decent solution.

I created the working regression test for this specific case. It needs some extra libraries as it requires a new file to execute in a separate process. However, it's the test we need for this scenario. Let me know if you have suggestions on the test.

@gaogaotiantian
Copy link
Member Author

Hi @markshannon , just fixed the conflict, is there anything I should update on this PR? Thanks!

markshannon
markshannon reviewed Oct 24, 2023
View reviewed changes
Copy link
Member

@markshannon markshannon left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

One style issue, otherwise looks good.

@markshannon markshannon merged commit e0afed7 into python:main Nov 3, 2023
@markshannon
Copy link
Member

Thanks for doing this

@bedevere-bot
Copy link

⚠️⚠️⚠️ Buildbot failure ⚠️⚠️⚠️

Hi! The buildbot s390x RHEL8 LTO 3.x has failed when building commit e0afed7.

What do you need to do:

  1. Don't panic.
  2. Check the buildbot page in the devguide if you don't know what the buildbots are or how they work.
  3. Go to the page of the buildbot that failed (https://buildbot.python.org/all/#builders/567/builds/5210) and take a look at the build logs.
  4. Check if the failure is related to this commit (e0afed7) or if it is a false positive.
  5. If the failure is related to this commit, please, reflect that on the issue and make a new Pull Request with a fix.

You can take a look at the buildbot page here:

https://buildbot.python.org/all/#builders/567/builds/5210

Summary of the results of the build (if available):

==

Click to see traceback logs 
remote: Enumerating objects: 40, done.        
remote: Counting objects:   2% (1/40)        
remote: Counting objects:   5% (2/40)        
remote: Counting objects:   7% (3/40)        
remote: Counting objects:  10% (4/40)        
remote: Counting objects:  12% (5/40)        
remote: Counting objects:  15% (6/40)        
remote: Counting objects:  17% (7/40)        
remote: Counting objects:  20% (8/40)        
remote: Counting objects:  22% (9/40)        
remote: Counting objects:  25% (10/40)        
remote: Counting objects:  27% (11/40)        
remote: Counting objects:  30% (12/40)        
remote: Counting objects:  32% (13/40)        
remote: Counting objects:  35% (14/40)        
remote: Counting objects:  37% (15/40)        
remote: Counting objects:  40% (16/40)        
remote: Counting objects:  42% (17/40)        
remote: Counting objects:  45% (18/40)        
remote: Counting objects:  47% (19/40)        
remote: Counting objects:  50% (20/40)        
remote: Counting objects:  52% (21/40)        
remote: Counting objects:  55% (22/40)        
remote: Counting objects:  57% (23/40)        
remote: Counting objects:  60% (24/40)        
remote: Counting objects:  62% (25/40)        
remote: Counting objects:  65% (26/40)        
remote: Counting objects:  67% (27/40)        
remote: Counting objects:  70% (28/40)        
remote: Counting objects:  72% (29/40)        
remote: Counting objects:  75% (30/40)        
remote: Counting objects:  77% (31/40)        
remote: Counting objects:  80% (32/40)        
remote: Counting objects:  82% (33/40)        
remote: Counting objects:  85% (34/40)        
remote: Counting objects:  87% (35/40)        
remote: Counting objects:  90% (36/40)        
remote: Counting objects:  92% (37/40)        
remote: Counting objects:  95% (38/40)        
remote: Counting objects:  97% (39/40)        
remote: Counting objects: 100% (40/40)        
remote: Counting objects: 100% (40/40), done.        
remote: Compressing objects:  11% (1/9)        
remote: Compressing objects:  22% (2/9)        
remote: Compressing objects:  33% (3/9)        
remote: Compressing objects:  44% (4/9)        
remote: Compressing objects:  55% (5/9)        
remote: Compressing objects:  66% (6/9)        
remote: Compressing objects:  77% (7/9)        
remote: Compressing objects:  88% (8/9)        
remote: Compressing objects: 100% (9/9)        
remote: Compressing objects: 100% (9/9), done.        
remote: Total 21 (delta 19), reused 12 (delta 11), pack-reused 0        
From https://github.com/python/cpython
 * branch                  main       -> FETCH_HEAD
Note: switching to 'e0afed7e276b6611a2142ec70a0440298d528305'.

You are in 'detached HEAD' state. You can look around, make experimental
changes and commit them, and you can discard any commits you make in this
state without impacting any branches by switching back to a branch.

If you want to create a new branch to retain commits you create, you may
do so (now or later) by using -c with the switch command. Example:

  git switch -c <new-branch-name>

Or undo this operation with:

  git switch -

Turn off this advice by setting config variable advice.detachedHead to false

HEAD is now at e0afed7e27 gh-103615: Use local events for opcode tracing (GH-109472)
Switched to and reset branch 'main'

Python/crossinterp.c:1472:1: warning: ‘_session_is_active’ defined but not used [-Wunused-function]
 _session_is_active(_PyXI_session *session)
 ^~~~~~~~~~~~~~~~~~

make: *** [Makefile:2067: buildbottest] Error 3

@bedevere-bot
Copy link

⚠️⚠️⚠️ Buildbot failure ⚠️⚠️⚠️

Hi! The buildbot AMD64 Windows11 Bigmem 3.x has failed when building commit e0afed7.

What do you need to do:

  1. Don't panic.
  2. Check the buildbot page in the devguide if you don't know what the buildbots are or how they work.
  3. Go to the page of the buildbot that failed (https://buildbot.python.org/all/#builders/1079/builds/2660) and take a look at the build logs.
  4. Check if the failure is related to this commit (e0afed7) or if it is a false positive.
  5. If the failure is related to this commit, please, reflect that on the issue and make a new Pull Request with a fix.

You can take a look at the buildbot page here:

https://buildbot.python.org/all/#builders/1079/builds/2660

Summary of the results of the build (if available):

==

Click to see traceback logs 
remote: Enumerating objects: 21, done.        
remote: Counting objects:   5% (1/19)        
remote: Counting objects:  10% (2/19)        
remote: Counting objects:  15% (3/19)        
remote: Counting objects:  21% (4/19)        
remote: Counting objects:  26% (5/19)        
remote: Counting objects:  31% (6/19)        
remote: Counting objects:  36% (7/19)        
remote: Counting objects:  42% (8/19)        
remote: Counting objects:  47% (9/19)        
remote: Counting objects:  52% (10/19)        
remote: Counting objects:  57% (11/19)        
remote: Counting objects:  63% (12/19)        
remote: Counting objects:  68% (13/19)        
remote: Counting objects:  73% (14/19)        
remote: Counting objects:  78% (15/19)        
remote: Counting objects:  84% (16/19)        
remote: Counting objects:  89% (17/19)        
remote: Counting objects:  94% (18/19)        
remote: Counting objects: 100% (19/19)        
remote: Counting objects: 100% (19/19), done.        
remote: Compressing objects:  12% (1/8)        
remote: Compressing objects:  25% (2/8)        
remote: Compressing objects:  37% (3/8)        
remote: Compressing objects:  50% (4/8)        
remote: Compressing objects:  62% (5/8)        
remote: Compressing objects:  75% (6/8)        
remote: Compressing objects:  87% (7/8)        
remote: Compressing objects: 100% (8/8)        
remote: Compressing objects: 100% (8/8), done.        
remote: Total 21 (delta 11), reused 13 (delta 11), pack-reused 2        
From https://github.com/python/cpython
 * branch                  main       -> FETCH_HEAD
Note: switching to 'e0afed7e276b6611a2142ec70a0440298d528305'.

You are in 'detached HEAD' state. You can look around, make experimental
changes and commit them, and you can discard any commits you make in this
state without impacting any branches by switching back to a branch.

If you want to create a new branch to retain commits you create, you may
do so (now or later) by using -c with the switch command. Example:

  git switch -c <new-branch-name>

Or undo this operation with:

  git switch -

Turn off this advice by setting config variable advice.detachedHead to false

HEAD is now at e0afed7e27 gh-103615: Use local events for opcode tracing (GH-109472)
Switched to and reset branch 'main'

Could Not Find R:\buildarea\3.x.ambv-bb-win11.bigmem\build\Lib\*.pyc
The system cannot find the file specified.
Could Not Find R:\buildarea\3.x.ambv-bb-win11.bigmem\build\PCbuild\python*.zip

Could Not Find R:\buildarea\3.x.ambv-bb-win11.bigmem\build\PCbuild\python*.zip

@gaogaotiantian gaogaotiantian mentioned this pull request Jan 23, 2024
Closed
@gaogaotiantian gaogaotiantian deleted the pep669-opcode-trace branch January 23, 2024 17:05
aisk pushed a commit to aisk/cpython that referenced this pull request Feb 11, 2024
@gaogaotiantian @aisk
pythongh-103615: Use local events for opcode tracing (pythonGH-109472)
4c539fa 
* Use local monitoring for opcode trace

* Remove f_opcode_trace_set

* Add test for setting f_trace_opcodes after settrace
Glyphack pushed a commit to Glyphack/cpython that referenced this pull request Sep 2, 2024
@gaogaotiantian @Glyphack
pythongh-103615: Use local events for opcode tracing (pythonGH-109472)
14cfc3c 
* Use local monitoring for opcode trace

* Remove f_opcode_trace_set

* Add test for setting f_trace_opcodes after settrace
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@brandtbucher brandtbucher Awaiting requested review from brandtbucher

@markshannon markshannon Awaiting requested review from markshannon markshannon is a code owner

Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.

test_sys_settrace tests are not independent
3 participants
@gaogaotiantian @markshannon @bedevere-bot