Severe performance degradation for tracing under 3.11

[nedbat]

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

• GH-93516: match logic of codeobject.c in _co_firsttraceable calculation #108028

[nedbat]

@pablogsal @markshannon

[Fidget-Spinner]

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]

One reproducer script with only coverage.py as a dependency:

from time import perf_counter
import coverage

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)

Here's some output of Visual Studio performance profiler:

On the current 3.10 branch (took 13.0 seconds):

Details

Function Name	Total CPU [unit, %]	Self CPU [unit, %]	Module
| - _PyEval_EvalFrameDefault	12606 (99.60%)	3594 (28.40%)	python310.dll
| - [External Call] tracer.cp310-win_amd64.pyd	2687 (21.23%)	1360 (10.75%)	tracer.cp310-win_amd64.pyd
| - maybe_call_line_trace	3731 (29.48%)	1158 (9.15%)	python310.dll
| - _PyCode_CheckLineNumber	1154 (9.12%)	1005 (7.94%)	python310.dll
| - call_trace	3322 (26.25%)	500 (3.95%)	python310.dll
| - PyLong_FromLong	358 (2.83%)	357 (2.82%)	python310.dll
| - _PyFrame_New_NoTrack	411 (3.25%)	346 (2.73%)	python310.dll
| - [External Code]	12527 (98.97%)	324 (2.56%)	Multiple modules
| - set_add_entry	291 (2.30%)	291 (2.30%)	python310.dll
| - lookdict_unicode_nodummy	288 (2.28%)	288 (2.28%)	python310.dll
| - call_trace_protected	2051 (16.20%)	282 (2.23%)	python310.dll
| - PyDict_GetItem	541 (4.27%)	262 (2.07%)	python310.dll

On the current main branch (took 126.9 seconds)

Details

Function Name	Total CPU [unit, %]	Self CPU [unit, %]	Module
| - _PyEval_EvalFrameDefault	123576 (99.75%)	48437 (39.10%)	python312.dll
| - _PyObject_GenericGetAttrWithDict	23038 (18.60%)	7204 (5.81%)	python312.dll
| - unicodekeys_lookup_unicode	5535 (4.47%)	5535 (4.47%)	python312.dll
| - _PyType_Lookup	7903 (6.38%)	5424 (4.38%)	python312.dll
| - PyObject_GetAttr	26969 (21.77%)	3634 (2.93%)	python312.dll
| - _PyFrame_Clear	3285 (2.65%)	2870 (2.32%)	python312.dll
| - _PyCode_CheckLineNumber	6036 (4.87%)	2732 (2.21%)	python312.dll

The first difference I notice is that there's a lot of overhead in some call to _PyObject_GenericGetAttrWithDict.

[sweeneyde]

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:

Details

lookup fib
lookup THIS_FILE
lookup stopped
lookup should_start_context
lookup started_context
lookup _activity
lookup data_stack
lookup cur_file_data
lookup cur_file_name
lookup last_line
lookup cur_file_name
lookup cur_file_data
lookup RESUME
lookup last_line
lookup _cached_bound_method_trace
lookup THIS_FILE
lookup stopped
lookup cur_file_data
lookup trace_arcs
lookup cur_file_data
lookup last_line
lookup _cached_bound_method_trace
lookup THIS_FILE
lookup stopped
lookup cur_file_data
lookup trace_arcs
lookup cur_file_data
lookup last_line
lookup _cached_bound_method_trace

[sweeneyde]

I now realize this is probably due to using the Python tracer rather than the C tracer, will try again.

[sweeneyde]

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]

This seems to suggest to me that this could be made much faster via a dedicated C API function:

https://github.com/nedbat/coveragepy/blob/master/coverage/ctracer/util.h#L41

#define MyCode_GetCode(co)      (PyObject_GetAttrString((PyObject *)(co), "co_code"))

[sweeneyde]

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]

Ah! PyCode_GetCode exists since #92168