Exceptions slow in 3.11, depending on location

[pochmann]

Bug report

Bug description:

(From Discourse)

Consider these two functions:

def short():
    try:
        if 0 == 1:
            unreached
        raise RuntimeError
    except RuntimeError:
        pass

def long():
    try:
        if 0 == 1:
            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached
            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached
            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached
            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached
            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached
            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached
            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached
            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached
            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached
            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached
        raise RuntimeError
    except RuntimeError:
        pass

The only difference is that long() has 100 unreached statements instead of just one. But it takes much longer in Python 3.11 (and a bit longer in Python 3.10). Times from @jamestwebber (here):

Python: 3.11.5 | packaged by conda-forge | (main, Aug 27 2023, 03:34:09) [GCC 12.3.0]
 176.5 ±  0.4 ns  short
 644.7 ±  0.6 ns  long

Python: 3.10.12 | packaged by conda-forge | (main, Jun 23 2023, 22:40:32) [GCC 12.3.0]
 150.7 ±  0.1 ns  short
 167.0 ±  0.2 ns  long

Why? Shouldn't it just jump over them all and be just as fast as short()?

Benchmark script

Attempt This Online!):

from timeit import timeit
from time import perf_counter as time
from statistics import mean, stdev
import sys


def short():
    try:
        if 0 == 1:
            unreached
        raise RuntimeError
    except RuntimeError:
        pass


def long():
    try:
        if 0 == 1:
            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached
            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached
            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached
            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached
            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached
            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached
            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached
            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached
            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached
            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached
        raise RuntimeError
    except RuntimeError:
        pass


funcs = short, long

for _ in range(3):
    times = {f: [] for f in funcs}
    def stats(f):
        ts = [t * 1e9 for t in sorted(times[f])[:5]]
        return f'{mean(ts):6.1f} ± {stdev(ts):4.1f} ns '
    for _ in range(100):
        for f in funcs:
            t = timeit(f, number=10**4) / 1e4
            times[f].append(t)
    for f in sorted(funcs, key=stats):
        print(stats(f), f.__name__)
    print()

print('Python:', sys.version)

In fact it takes time linear in how many unreached statements there are. Times for 100 to 100000 unreached statements (on one line, before the try):

   100     2.6 μs
  1000    24.3 μs
 10000   253.3 μs
100000  2786.2 μs

Benchmark script

from time import perf_counter as time
from timeit import repeat

for e in range(2, 6):
    n = 10 ** e
    exec(f'''def f():
        if 0 == 1:
            {'unreached;' * n}
        try:
            raise RuntimeError
        except RuntimeError:
            pass''')
    number = 10**6 // n
    t = min(repeat(f, number=number)) / number
    print(f'{n:6} {t * 1e6 :7.1f} μs')

Attempt This Online!

The slowness happens when the unreached statements are anywhere before the raise, and not when they're anywhere after the raise (demo). So it seems what matters is location of the raise in the function. Long code before it somehow makes it slow.

This has a noticeable impact on real code I wrote (assuming I pinpointed the issue correctly): two solutions for a task, and one was oddly slower (~760 vs ~660 ns) despite executing the exact same sequence of bytecode operations. Just one jump length differed, leading to a raise at a larger address.

Benchmark script with those two solutions and the relevant test case:

The functions shall return the one item from the iterable, or raise an exception if there are fewer or more than one. Testing with an empty iterable, both get the iterator, iterate it (nothing, since it's empty), then raise. The relevant difference appears to be that the slower one has the raise written at the bottom, whereas the faster one has it near the top.

Sample times:

 664.4 ±  8.6 ns  one_sequential
 762.1 ± 28.8 ns  one_nested

Python: 3.11.4 (main, Jun 24 2023, 10:18:04) [GCC 13.1.1 20230429]

Code:

from timeit import timeit
from statistics import mean, stdev
from itertools import repeat, starmap, islice
import sys


def one_nested(iterable, too_short=None, too_long=None):
    it = iter(iterable)
    for first in it:
        for second in it:
            raise too_long or ValueError(
                'Expected exactly one item in iterable, but',
                f'got {first!r}, {second!r}, and perhaps more.'
            )
        return first
    raise too_short or ValueError('too few items in iterable (expected 1)')


def one_sequential(iterable, too_short=None, too_long=None):
    it = iter(iterable)

    for first in it:
        break
    else:
        raise too_short or ValueError('too few items in iterable (expected 1)')

    for second in it:
        raise too_long or ValueError(
            'Expected exactly one item in iterable, but '
            f'got {first!r}, {second!r}, and perhaps more.'
        )

    return first


funcs = one_nested, one_sequential

def empty(f):
    iterable = iter(())
    too_short = RuntimeError()
    for _ in repeat(None, 10**4):
        try:
            f(iterable, too_short)
        except RuntimeError:
            pass

for case in empty,:

    times = {f: [] for f in funcs}
    def stats(f):
        ts = [t * 1e9 for t in sorted(times[f])[:5]]
        return f'{mean(ts):6.1f} ± {stdev(ts):4.1f} ns '
    for _ in range(100):
        for f in funcs:
            t = timeit(lambda: case(f), number=1) / 1e4
            times[f].append(t)
    for f in sorted(funcs, key=stats):
        print(stats(f), f.__name__)
    print()

print('Python:', sys.version)

Attempt This Online!

CPython versions tested on:

3.10, 3.11

Operating systems tested on:

Linux, macOS

Linked PRs

• gh-109181: Speed up Traceback object creation by lazily compute the line number #111548
• [3.11] gh-109181: Speed up Traceback object creation by lazily compute the line number (GH-111548) #111550
• [3.12] gh-109181: Speed up Traceback object creation by lazily compute the line number (GH-111548) #111551
• [3.12] gh-109181: Fix refleak in tb_get_lineno() #111948
• [3.11] [3.12] gh-109181: Fix refleak in tb_get_lineno() (GH-111948) #111951

[sunmy2019]

bisect shows the regression starts at #26955 for the implementation of pep-0657
PEP 657 – Include Fine Grained Error Locations in Tracebacks

The extra time must be caused by finding the error locations.

[sunmy2019]

They use an O(n) implementation internally.

[nielstron]

Just for the sake of completeness, the length of unreachable code without a raise statement does not influence the computation time.

Benchmark script

from time import perf_counter as time
from timeit import repeat

for e in range(2, 6):
    n = 10 ** e
    exec(f'''def f():
        if 0 == 1:
            {'unreached;' * n}
        return''')
    number = 10**6 // n
    t = min(repeat(f, number=number)) / number
    print(f'{n:6} {t * 1e6 :7.1f} μs')

By comparing the performance record between the two we can see that Addr2Line is the culprit

Perf screenshots

And indeed, when commenting out the corresponding loops I see a reduction in the runtime

Same test script as initally provided, now with commented out loop

   100     0.2 μs
  1000     0.2 μs
 10000     0.2 μs
100000     0.2 μs
1000000     0.3 μs

vs

   100     0.6 μs
  1000     4.7 μs
 10000    46.0 μs
100000   495.2 μs
1000000  5049.9 μs

More specifically, it seems most time is spent looking for 0 bytes here. This is about where my current understanding of what this code even does ends :)

[nielstron]

@AlexWaygood I am also experiencing this slowdown in python 3.10.12 (since you added 3.11, 3.12 and 3.13)

[AlexWaygood]

@AlexWaygood I am also experiencing this slowdown in python 3.10.12 (since you added 3.11, 3.12 and 3.13)

Python 3.10 is old enough that it is now only accepting bugfixes if they relate to security issues, and this isn't a security issue. For us, therefore, this is only an issue for Python 3.11+, even if it can be reproduced on Python 3.10.

[iritkatriel]

@pablogsal and thoughts on this?

[pablogsal]

@pablogsal and thoughts on this?

I am currently on sick leave so I cannot look at this in detail but I feel this is the balance between the compression to save disk size and the speed to "uncompress" the line table.

On the other hand maybe we could defer the computation of the line table offsets only when exceptions buble up to top level, but it may be too late at that point so we may need to save extra information and maybe even the code object if is not reachable already in all cases.

In any case, I don't think this is a bug. It may qualify as a regression if we all agree but I am not even sure if I would call it that, since is just a consequence of the feature.

[sunmy2019]

I agree it's not a bug. Extra cost for new features improving error messages is fine.

Someone may want a switch to disable this feature, but I would argue that you should rather keep the try ... except ... block as short as possible.

[pablogsal]

I agree it's not a bug. Extra cost for new features improving error messages is fine.

Someone may want a switch to disable this feature, but I would argue that you should rather keep the try ... except ... block as short as possible.

I think we can make that work with -X no_debug_ranges or PYTHONNODEBUGRANGES

[pablogsal]

Backporting to 3.12 and 3.11 as technically this is a regression

[vstinner]

Backporting to 3.12 and 3.11 as technically this is a regression

These changes introduced references leaks in 3.11 and 3.12 branches: see issue gh-111947.