sys.settrace suffers quadratic behavior for large dictionary literals on 3.12+

[nedbat]

Bug report

Bug description:

Using a trace function with sys.settrace, performance suffers when importing a large dictionary literal. The performance exhibits quadratic time complexity on 3.12 and up. It is fine on 3.11.

This originated with a coverage.py bug report: nedbat/coveragepy#1906

To reproduce, create make_mapping.py:

"""
Create a really large dict to import.
"""

import random

print("MAPPING = {")
for n in range(25_000):
    print(f"    '{n:08d}': {n},")
print("}")

and trace_it.py:

import linecache, sys, time

t0 = tlast = time.monotonic_ns()

def trace(frame, event, arg):
    global tlast
    if "mapping.py" in frame.f_code.co_filename:
        lineno = frame.f_lineno
        now = time.monotonic_ns()
        print("{:12d} ({}): {} {:05d}".format(
            now - t0, now - tlast,
            event[:4], lineno,
        ))
        tlast = now
    return trace

print(sys.version)
sys.settrace(trace)

import mapping

Then, create the large mapping, and run trace_it.py on multiple versions, and look at the timings:

python3 make_mapping.py > mapping.py
python3.11 trace_it.py > 11.out
python3.12 trace_it.py > 12.out
python3.13 trace_it.py > 13.out
python3.14 trace_it.py > 14.out
grep 'line \d[05]000' *.out

These are the results I see. The parenthetical numbers are nanoseconds since the last output line:

11.out:    76131833 (1917): line 05000
11.out:    86116875 (917): line 10000
11.out:    96115250 (917): line 15000
11.out:   106099958 (958): line 20000
11.out:   116161416 (875): line 25000

12.out:   803728958 (148833): line 05000
12.out:  3009835500 (293042): line 10000
12.out:  6750690750 (444833): line 15000
12.out: 11966781625 (596292): line 20000
12.out: 18720473667 (739000): line 25000

13.out:   443250333 (75125): line 05000
13.out:  1565451416 (147583): line 10000
13.out:  3447408625 (220625): line 15000
13.out:  6130466958 (294458): line 20000
13.out:  9455595416 (370500): line 25000

14.out:   445441625 (89291): line 05000
14.out:  1556189584 (152250): line 10000
14.out:  3410512125 (220625): line 15000
14.out:  6007919334 (366584): line 20000
14.out:  9369414792 (375083): line 25000

CPython versions tested on:

3.11, 3.12, 3.13, 3.14

Operating systems tested on:

macOS

Linked PRs

• GH-127953: Make line number lookup O(1) regardless of the size of the code object #128350
• [3.13] GH-127953: Make line number lookup O(1) regardless of the size of the code object #129127
• [3.12] GH-127953: Make line number lookup O(1) regardless of the size of the code object (GH-129127) #132268

[nedbat]

I bisected CPython and it is perhaps no surprise that the problem started with:

commit 411b1692811b2ecac59cb0df0f920861c7cf179a
Author: Mark Shannon <mark@hotpy.org>
Date:   Wed Apr 12 12:04:55 2023 +0100

    GH-103082: Implementation of PEP 669: Low Impact Monitoring for CPython (GH-103083)

/cc @markshannon

[gaogaotiantian]

This is a known issue, which I tried to alleviate in #118127. The problem is getting the line number - with the new mechanism, if a function(module) is super long, calculating the line number would be difficult. We can solve this for good, but we need extra run-time memory (plenty of those) to remember the line number. Considering how rare this case is, it might not be worth it to make the trade off.

[nedbat]

Considering how rare this case is, it might not be worth it to make the trade off.

Do you have a suggestion for the person who cannot move up from 3.11?

[gaogaotiantian]

Is ruling out that specific file a possible solution? If coverage.py does not access f_lineno for events on that specific file, the speed should be normal. If it's a file that contains a giant mapping, coverage for that specific file should not be needed I assume.

I know this is not a perfect solution, maybe there is a way to solve this in a better way. I did not manage to do it without too much sacrifice on memory but that might just because of my limited knowledge of the topic. Anyone should feel free to try it out - I think I explained the reason of this slow down in the PR mentioned above.

[nedbat]

Dup of #107674 (which I also wrote, oops!)

[nedbat]

(Continuing here for a moment...) If I change the trace_it.py code to return None, then 11.out and 12.out both are very short:

3.11.11 (main, Dec  3 2024, 19:47:16) [Clang 16.0.0 (clang-1600.0.26.4)]
    91913042 (91913042): call 00000

and

3.12.8 (main, Dec  3 2024, 19:49:11) [Clang 16.0.0 (clang-1600.0.26.4)]
    81839750 (81839750): call 00000

but 3.12 still takes a long time to complete. Are we calculating the line number even when we don't need to call the trace function? This is a simulation of omitting the large file from coverage.py, which doesn't solve the problem.

[nedbat]

BTW, the same is true of tracing very long functions: even returning None from the trace function, 3.12 takes much longer than 3.11. The effect isn't as pronounced as with a dict literal.

[gaogaotiantian]

That's because the optimization is not backported (it's not a bug fix unfortunately). It should be different on 3.13 - and we can't really do anything about it.