Description
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
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')
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)
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