GeezerVison is showing github.com — sys.settrace dramatic slowdown in 3.12 · Issue #107674 · python/cpython
sys.settrace dramatic slowdown in 3.12 #107674Labels interpreter-core(Objects, Python, Grammar, and Parser dirs)(Objects, Python, Grammar, and Parser dirs)performancePerformance or resource usagePerformance or resource usagetype-bugAn unexpected behavior, bug, or errorAn unexpected behavior, bug, or error DescriptionBug report
Checklist
- I am confident this is a bug in CPython, not a bug in a third-party project
- I have searched the CPython issue tracker, and am confident this bug has not been reported before
A clear and concise description of the bug
A bug report in coverage (coveragepy/coveragepy#1665) is reduced here to a pure do-nothing trace function for sys.settrace.
Reproduction:
% git clone https://github.com/nedbat/ndindex
% cd ndindex
% python3.11 -VV
Python 3.11.4 (main, Jun 7 2023, 08:42:37) [Clang 14.0.3 (clang-1403.0.22.14.1)]
% python3.11 -m venv v311
% ./v311/bin/pip install numpy
% python3.12 -VV
Python 3.12.0b4 (main, Jul 11 2023, 20:38:26) [Clang 14.0.3 (clang-1403.0.22.14.1)]
% python3.12 -m venv v312
% ./v312/bin/pip install --pre --extra-index https://pypi.anaconda.org/scientific-python-nightly-wheels/simple numpy
% # Run the code without the trace function.
% for x in 1 2 3; time ./v311/bin/python -m ndindex.tests.justdoit notrace
./v311/bin/python -m ndindex.tests.justdoit notrace 7.05s user 0.37s system 108% cpu 6.813 total
./v311/bin/python -m ndindex.tests.justdoit notrace 7.04s user 0.34s system 109% cpu 6.724 total
./v311/bin/python -m ndindex.tests.justdoit notrace 7.00s user 0.35s system 109% cpu 6.696 total
% # 3.12 is slightly faster without the trace function.
% for x in 1 2 3; time ./v312/bin/python -m ndindex.tests.justdoit notrace
./v312/bin/python -m ndindex.tests.justdoit notrace 6.56s user 0.30s system 106% cpu 6.422 total
./v312/bin/python -m ndindex.tests.justdoit notrace 6.48s user 0.31s system 106% cpu 6.359 total
./v312/bin/python -m ndindex.tests.justdoit notrace 6.38s user 0.28s system 107% cpu 6.217 total
% # 3.11 with tracing is about 3x slower.
% for x in 1 2 3; time ./v311/bin/python -m ndindex.tests.justdoit trace
./v311/bin/python -m ndindex.tests.justdoit trace 22.64s user 0.51s system 101% cpu 22.772 total
./v311/bin/python -m ndindex.tests.justdoit trace 21.92s user 0.46s system 101% cpu 21.979 total
./v311/bin/python -m ndindex.tests.justdoit trace 21.55s user 0.35s system 102% cpu 21.379 total
% # 3.12 with tracing is 7x slower.
% for x in 1 2 3; time ./v312/bin/python -m ndindex.tests.justdoit trace
./v312/bin/python -m ndindex.tests.justdoit trace 49.47s user 0.40s system 100% cpu 49.676 total
./v312/bin/python -m ndindex.tests.justdoit trace 49.53s user 0.39s system 100% cpu 49.784 total
./v312/bin/python -m ndindex.tests.justdoit trace 50.44s user 0.38s system 100% cpu 50.739 total
I don't know if the unusual numpy build has something to do with this.
Linked PRs
Reacted by Niko Föhr and Cornelius Roemer Activityneonene commented on Aug 6, 2023 This issue can be seen starting from the commit 411b169 with usual numpy-1.25.2. AlexWaygood commented on Aug 7, 2023 added a commit that references this issue on Aug 10, 2023GH-107674: Avoid allocating boxed ints for `sys.settrace` line events (… nedbat commented on Oct 24, 2023 nedbat commented on Oct 30, 2023 iritkatriel commented on Oct 31, 2023 gaogaotiantian commented on Feb 4, 2024 Hi @nedbat , I circled back to this issue. If you are still interested, could you try the patch of #114986 and see if the result is improved? nedbat commented on Feb 15, 2024 gaogaotiantian commented on Feb 15, 2024 Oh, did you test it with an empty trace function? nedbat commented on Feb 15, 2024 I will do more tests, but the ultimate goal is to perform better in real-world scenarios. Here is more data from a subset of the test suite (-k test_chunking), which looks much more promising. It's hard to get consistent numbers, but this looks good. I would merge this change.
| Python version |
no tracing |
Python trace |
C trace |
| 3.11.8 |
1.19s |
7.39s |
2.46s |
| 3.12.2 |
1.12s |
11.57s |
3.71s |
| 3.13.0a3+ heads/main:a95b1a56bb |
1.14s |
10.37s |
3.89s |
| 3.13.0a3+ heads/pr/114986:cb09c55758 |
1.14s |
6.48s |
2.91s |
gaogaotiantian commented on Feb 15, 2024 Thank you for the test. Yes the PR only improves the performance of the actual trace function - which is normally the major cost for tracing tools. Good to know it helps with the more real-life benchmark. Unfortunately, due to the change of the tracing mechanism, the overhead for sys.settrace will always be larger than the old way - I did not see a quick solution to that. nedbat commented on Feb 12, 2025 I continue to get people reporting serious performance problems on 3.12. Is there any chance of an improvement? junkmd commented on Feb 14, 2025 Considering the issue observed in enthought/comtypes#775, where execution time increased nearly tenfold, there is a performance "regression" in Python 3.12.
Only one bugfix release remains for Python 3.12:
https://pythonpeps.python.org/pep-0693/
If #107841 is not merged by then, I believe the Python community will miss an opportunity to reconsider this issue.
If "the fix patch" is merged before Python 3.12 transitions to security-fix only status, I would accept enabling coverage measurement in the comtypes CI tests for all Python versions (and waiting until 3.12.10 is released). Otherwise, only Python 3.12 will be tested without coverage measurement in the comtypes CI pipeline.
As discussed in #107841, I understand that this issue doesn't involve "broken" programs but rather a "performance improvement", and that the changes are complex to accept during the bugfix phase. However, fixing this could potentially benefit projects and the wider ecosystem running on Python 3.12.
I would like to, once again, hear the opinions of the core developers and the community on this matter. Reacted by Cornelius Roemer gaogaotiantian commented on Feb 14, 2025 Ah, @markshannon merged #128350 in main but did not backport it to 3.12 and 3.13 due to conflicts. #107841 is not the problem fixer. I believe backporting #128350 should fix the issue in 3.12 and 3.13. junkmd commented on Feb 18, 2025 I tested whether #107841 is the problem fixer.
I built Python from v3.12.8 and also from the 3.12 branch with 37d8b90 cherry-picked.
And I compared the execution time of comtypes test cases.
| with cov |
37d8b90 changes |
Python 3.12.8 |
| yes |
1101.106s |
1254.337s |
| no |
57.869s |
46.481s |
The build with 37d8b90 changes is about 153s faster than v3.12.8.
However, this performance improvement is still not significant.
I haven't tested backporting #128350 yet because I'm not sure how to resolve conflicts. gaogaotiantian commented on Apr 25, 2025 I think we can close this issue now. The fix did not make 3.12 as it missed the last bug fix release. It was backported to 3.13 though. I don't think we have more tasks for this issue anymore. jack-mcivor commented on Jun 17, 2025
The fix did not make 3.12 as it missed the last bug fix release.
Is this true? I found this issue from the changelog of 3.12.10, which seems to suggest the fix made it in?
gh-107674: Fixed performance regression in sys.settrace.
corneliusroemer commented on Jul 20, 2025
I think we can close this issue now. The fix did not make 3.12 as it missed the last bug fix release. It was backported to 3.13 though. I don't think we have more tasks for this issue anymore.
Yep, closed as not planned/won't fix. The 3.13 performance looks as good as 3.11, even better in my own benchmarks against https://github.com/nextstrain/augur with pytest on an M4 Max using conda-forge binaries.
Python 3.13.5
no-coverage: Time (mean ± σ): 5.777 s ± 0.178 s [User: 6.464 s, System: 2.464 s]
coverage : Time (mean ± σ): 8.381 s ± 0.217 s [User: 11.473 s, System: 4.635 s]
Python 3.12.11
no-coverage: Time (mean ± σ): 5.913 s ± 0.079 s [User: 6.347 s, System: 2.519 s]
coverage : Time (mean ± σ): 25.778 s ± 0.190 s [User: 28.985 s, System: 4.644 s]
Python 3.11.13
no-coverage: Time (mean ± σ): 5.912 s ± 0.228 s [User: 6.500 s, System: 2.480 s]
coverage : Time (mean ± σ): 8.806 s ± 0.332 s [User: 12.167 s, System: 4.493 s]
MetadataMetadatainterpreter-core(Objects, Python, Grammar, and Parser dirs)(Objects, Python, Grammar, and Parser dirs)performancePerformance or resource usagePerformance or resource usagetype-bugAn unexpected behavior, bug, or errorAn unexpected behavior, bug, or error DevelopmentNo branches or pull requestsIssue actions
|