sys.settrace dramatic slowdown in 3.12#107674
Description
Bug 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
- GH-107674: Avoid allocating boxed ints for
sys.settraceline events #107780 - [3.12] GH-107674: Avoid allocating boxed ints for
sys.settraceline events (GH-107780) #107841 - gh-107674: Improve performance of
sys.settrace#114986 - gh-107674: Improve performance of
sys.settrace#117133 - gh-107674: Remove some unnecessary code in instrumentation code #117393
- gh-107674: Lazy load line number to improve performance of tracing #118127