Closed
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:
passThe 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
Metadata
Metadata
Assignees
Labels
only security fixesonly security fixesonly security fixesonly security fixesbugs and security fixesbugs and security fixes(Objects, Python, Grammar, and Parser dirs)(Objects, Python, Grammar, and Parser dirs)Performance or resource usagePerformance or resource usageAn unexpected behavior, bug, or errorAn unexpected behavior, bug, or error