GeezerVison is showing github.com — Severe performance degradation for tracing under 3.11 · Issue #93516 · python/cpython
Severe performance degradation for tracing under 3.11 #93516Labels 3.11only security fixesonly security fixesinterpreter-core(Objects, Python, Grammar, and Parser dirs)(Objects, Python, Grammar, and Parser dirs)type-bugAn unexpected behavior, bug, or errorAn unexpected behavior, bug, or error Description
Bug report
Coverage.py is seeing a significant increase in overhead for tracing code in 3.11 compared to 3.10: coveragepy/coveragepy#1287
As an example:
| cov |
proj |
python3.10 |
python3.11 |
3.11 vs 3.10 |
| none |
bug1339.py |
0.184 s |
0.142 s |
76% |
| none |
bm_sudoku.py |
10.789 s |
9.901 s |
91% |
| none |
bm_spectral_norm.py |
14.305 s |
9.185 s |
64% |
| 6.4.1 |
bug1339.py |
0.450 s |
0.854 s |
189% |
| 6.4.1 |
bm_sudoku.py |
27.141 s |
55.504 s |
204% |
| 6.4.1 |
bm_spectral_norm.py |
36.793 s |
67.970 s |
184% |
(This is the output of lab/benchmark.py.)
Your environment
- CPython versions tested on: 3.10, 3.11
- Operating system and architecture: MacOS, Intel
Linked PRs
Reacted by Aleksander Vognild Burkow, Mike Fiedler and Fantom_sunday Activitynedbat commented on Jun 5, 2022 Fidget-Spinner commented on Jun 5, 2022 Related issue where a user reported that code with cProfile slowed down 1.6x, and the only thing I could pinpoint was that tracing itself slowed down, not cProfile #93381. sweeneyde commented on Jun 6, 2022 sweeneyde commented on Jun 6, 2022 sweeneyde commented on Jun 6, 2022 I now realize this is probably due to using the Python tracer rather than the C tracer, will try again. sweeneyde commented on Jun 6, 2022 Okay, now with Code coverage for Python, version 6.4.1 with C extension.
Script used:
import coverage
from time import perf_counter
def fib(n):
if n <= 1:
return n
else:
return fib(n-1) + fib(n-2)
t0 = perf_counter()
cov = coverage.Coverage()
cov.start()
fib(35)
cov.stop()
cov.save()
t1 = perf_counter()
print(t1 - t0)
Profile on 3.10 branch: took 13.3 seconds
Functions taking more than 1% of CPU:
| Function Name |
Total CPU [unit, %] |
Self CPU [unit, %] |
Module |
| | - _PyEval_EvalFrameDefault |
12372 (99.78%) |
3540 (28.55%) |
python310.dll |
| | - [External Call] tracer.cp310-win_amd64.pyd |
2769 (22.33%) |
1474 (11.89%) |
tracer.cp310-win_amd64.pyd |
| | - maybe_call_line_trace |
3872 (31.23%) |
1206 (9.73%) |
python310.dll |
| | - _PyCode_CheckLineNumber |
1168 (9.42%) |
988 (7.97%) |
python310.dll |
| | - call_trace |
3431 (27.67%) |
548 (4.42%) |
python310.dll |
| | - PyLong_FromLong |
370 (2.98%) |
369 (2.98%) |
python310.dll |
| | - _PyFrame_New_NoTrack |
385 (3.11%) |
338 (2.73%) |
python310.dll |
| | - lookdict_unicode_nodummy |
324 (2.61%) |
324 (2.61%) |
python310.dll |
| | - call_trace_protected |
2107 (16.99%) |
287 (2.31%) |
python310.dll |
| | - frame_dealloc |
270 (2.18%) |
270 (2.18%) |
python310.dll |
| | - set_add_entry |
264 (2.13%) |
264 (2.13%) |
python310.dll |
| | - PyDict_GetItem |
579 (4.67%) |
255 (2.06%) |
python310.dll |
| | - _PyEval_MakeFrameVector |
633 (5.11%) |
248 (2.00%) |
python310.dll |
| | - _PyEval_Vector |
12372 (99.78%) |
196 (1.58%) |
python310.dll |
| | - PyLineTable_NextAddressRange |
180 (1.45%) |
180 (1.45%) |
python310.dll |
| | - call_function |
12372 (99.78%) |
169 (1.36%) |
python310.dll |
| | - PyObject_RichCompare |
457 (3.69%) |
169 (1.36%) |
python310.dll |
| | - binary_op1 |
486 (3.92%) |
157 (1.27%) |
python310.dll |
| | - long_richcompare |
207 (1.67%) |
157 (1.27%) |
python310.dll |
Profile on main branch: took 23.0 seconds
Functions taking more than 1% of CPU:
| Function Name |
Total CPU [unit, %] |
Self CPU [unit, %] |
Module |
| | - _PyEval_EvalFrameDefault |
22180 (99.87%) |
4448 (20.03%) |
python312.dll |
| | - _PyCode_CheckLineNumber |
5389 (24.27%) |
2583 (11.63%) |
python312.dll |
| | - maybe_call_line_trace |
6461 (29.09%) |
1966 (8.85%) |
python312.dll |
| | - retreat |
2242 (10.10%) |
1644 (7.40%) |
python312.dll |
| | - [External Call] tracer.cp312-win_amd64.pyd |
6274 (28.25%) |
1428 (6.43%) |
tracer.cp312-win_amd64.pyd |
| | - get_line_delta |
1162 (5.23%) |
1162 (5.23%) |
python312.dll |
| | - unicodekeys_lookup_unicode |
844 (3.80%) |
728 (3.28%) |
python312.dll |
| | - _Py_dict_lookup |
1476 (6.65%) |
632 (2.85%) |
python312.dll |
| | - call_trace |
9802 (44.14%) |
630 (2.84%) |
python312.dll |
| | - siphash13 |
442 (1.99%) |
442 (1.99%) |
python312.dll |
| | - PyUnicode_New |
745 (3.35%) |
376 (1.69%) |
python312.dll |
| | - pymalloc_alloc |
362 (1.63%) |
362 (1.63%) |
python312.dll |
| | - _PyType_Lookup |
1786 (8.04%) |
319 (1.44%) |
python312.dll |
| | - set_add_entry |
271 (1.22%) |
271 (1.22%) |
python312.dll |
| | - PyDict_GetItem |
824 (3.71%) |
242 (1.09%) |
python312.dll |
| | - call_trace_protected |
8562 (38.55%) |
236 (1.06%) |
python312.dll |
| | - PyNumber_Subtract |
449 (2.02%) |
221 (1.00%) |
python312.dll |
sweeneyde commented on Jun 6, 2022 sweeneyde commented on Jun 6, 2022 Indeed, on main, if I add printf("lookup %s\n", (const char *)PyUnicode_DATA(key)); to the top of unicodekeys_lookup_unicode and run that fib script, I get the following hot loop repeated over and over:
lookup fib
lookup C:\Users\sween\Source\Repos\cpython2\cpython\cover.py
lookup C:\Users\sween\Source\Repos\cpython2\cpython\cover.py
lookup co_code
lookup fib
lookup C:\Users\sween\Source\Repos\cpython2\cpython\cover.py
lookup C:\Users\sween\Source\Repos\cpython2\cpython\cover.py
lookup co_code
...
Each of these calls to PyObject_GetAttrString(..., "co_code") requires PyUnicode_FromString->unicode_decode_utf8->PyUnicode_New->_PyObject_Malloc, followed by PyObject_GetAttr->_PyObject_GenericGetAttrWithDict->_PyType_Lookup->find_name_in_mro->(unicode_hash+_Py_Dict_Lookup)->unicodekeys_lookup_unicode, where it should be just a C API function call. sweeneyde commented on Jun 6, 2022 Ah! PyCode_GetCode exists since #92168 markshannon commented on Jun 6, 2022 Some performance degradation under tracing is expected, but not as much as reported.
This is a deliberate tradeoff: faster execution when not tracing, for slower execution when tracing.
From the profiles that @sweeneyde gathered it looks like we are seeing slowdowns in:
- _PyEval_EvalFrameDefault, which is expected
- Calculation of line numbers. This is probably due to the new line table format.
The new line number table gives better error messages without taking up too much extra space, but it is more complex and thus slower to parse.
We should be able to speed it up, but don't expect things to be as fast as 3.10. Sorry.
Once coveragepy/coveragepy#1394 is merged, we can look at the profile again to see if much has changed. sweeneyde commented on Jun 6, 2022
New profile of fib_cover.py on main branch, with the PyCode_GetCode addition (took 18.1 seconds)
| Function Name |
Total CPU [unit, %] |
Self CPU [unit, %] |
Module |
| | - _PyEval_EvalFrameDefault |
19239 (99.66%) |
4481 (23.21%) |
python312.dll |
| | - _PyCode_CheckLineNumber |
5344 (27.68%) |
2676 (13.86%) |
python312.dll |
| | - maybe_call_line_trace |
6397 (33.14%) |
1997 (10.34%) |
python312.dll |
| | - retreat |
2197 (11.38%) |
1629 (8.44%) |
python312.dll |
| | - [External Call] tracer.cp312-win_amd64.pyd |
3073 (15.92%) |
1360 (7.04%) |
tracer.cp312-win_amd64.pyd |
| | - get_line_delta |
1038 (5.38%) |
1038 (5.38%) |
python312.dll |
| | - call_trace |
6630 (34.34%) |
605 (3.13%) |
python312.dll |
| | - unicodekeys_lookup_unicode |
549 (2.84%) |
548 (2.84%) |
python312.dll |
| | - _Py_dict_lookup |
1060 (5.49%) |
511 (2.65%) |
python312.dll |
| | - PyDict_GetItem |
929 (4.81%) |
266 (1.38%) |
python312.dll |
| | - set_add_entry |
265 (1.37%) |
265 (1.37%) |
python312.dll |
| | - PyNumber_Subtract |
447 (2.32%) |
226 (1.17%) |
python312.dll |
| | - call_trace_protected |
5408 (28.01%) |
222 (1.15%) |
python312.dll |
| | - initialize_locals |
199 (1.03%) |
199 (1.03%) |
python312.dll |
I wonder: would there be any way to retain some specializations during tracing? Some specialized opcodes are certainly incorrect to use during tracing, e.g., STORE_FAST__LOAD_FAST. However, couldn't others be retained, e.g. LOAD_GLOBAL_MODULE, or any specialized opcode that covers only one unspecialized opcode? (EDIT: maybe not, if it uses NOTRACE_DISPATCH()) pablogsal commented on Jun 6, 2022
We should be able to speed it up, but don't expect things to be as fast as 3.10. Sorry.
Well, two times slower than 3.10, as some of @nedbat's benchmarks show, is not acceptable in my opinion. We should try to get this below 20% at the very least.
I marked this as a release blocker and this will block any future releases. Fidget-Spinner commented on Jun 30, 2022 I now agree with Gregory and Alex that the performance regression is within acceptable levels. IMO we can leave this issue open but it shouldn't block the 3.11 release. jpe commented on Jul 1, 2022 The current sources seem to be significantly faster than b3.
Can the line number checks be eliminated when frame->f_trace_lines is false? This wouldn't help with coverage but would help debuggers that set f_trace_lines to false when line events aren't needed. fabioz commented on Jul 1, 2022 I just reran the performance for pydevd with the current tip. The numbers haven't changed from the last run (it's still in the range of 45 -> 70 percent slower depending on the use case, so, at least for pydevd the current tip measurements are very close to the beta 3 measurements).
| Benchmark |
Python 3.10 |
Python 3.11 tip ( abf5f5c ) |
Slower than 3.10 in % |
| method_calls_with_breakpoint |
0,25 |
0,363 |
45,20% |
| method_calls_without_breakpoint |
0,247 |
0,375 |
51,82% |
| method_calls_with_step_over |
0,236 |
0,376 |
59,32% |
| method_calls_with_exception_breakpoint |
0,249 |
0,389 |
56,22% |
| global_scope_1_with_breakpoint |
0,557 |
0,937 |
68,22% |
| global_scope_2_with_breakpoint |
0,238 |
0,343 |
44,12% |
jpe commented on Jul 1, 2022 Hmm, I may be confusing myself but I'm seeing tip take about 50% of the time of b3 when running one of our test files. I'm testing with a C trace function that doesn't do anything except return 0. Looking at the diffs since b3, I think performance partially depends on the number of code objects. P403n1x87 commented on Jul 6, 2022 On the off chance that some native flame graphs could be of help here. These are taken from running @nedbat's benchmarks for the bm_sudoku case, through austinp, comparing the tip of 3.11 (b22f9d6) against 3.10.5. The side view also shows a top-like report, sorted by own time.
bm_sudoku with 3.10
bm_sudoku with 3.11
pablogsal commented on Jul 6, 2022 Thanks for the report @P403n1x87! Unfortunately, the results you show are not very useful (is mostly what we are already getting by running perf) because what we need to understand is what linear or non-linear combination of the changes we did are affecting the coverage numbers. The flame graphs and tables show the difference between 3.10.5 and 3.11 which are two completely code paths for everything (they don't even have the same instructions). What we need to understand is the relative cost of the coverage-relative machinery before and after every change that we did that could affect this. Unfortunately tracing over all the interpreter is too unstable and noisy (and not granular enough) to give us insight.
But thanks a lot for the help 🙏, I am sure that if we need to measure the interaction between the benchmark python code and the interpreter we can use your tool 👍 StanFromIreland commented on Apr 25, 2025 This needs to be removed from the differed/release blocker project. (Along with a few others) markshannon commented on May 6, 2025 There are going to be no direct fixes for this issue, but I expect it to become a non-issue over the course of the 3.15 development cycle for two reasons:
- Now that sys.monitoring supports efficient branch monitoring, coverage.py will use it by default and the performance impact on coverage will go. And really, it is only coverage that this matters for. All debuggers now use sys.monitoring.
- As we move to tagged integers the boxing/unboxing overhead for line events will disappear, which is the main cause of the slowdown.
@nedbat is my statement about coverage.py correct?
MetadataMetadata3.11only security fixesonly security fixesinterpreter-core(Objects, Python, Grammar, and Parser dirs)(Objects, Python, Grammar, and Parser dirs)type-bugAn unexpected behavior, bug, or errorAn unexpected behavior, bug, or error StatusShow more project fields
DevelopmentNo branches or pull requestsIssue actions
|
