René's URL Explorer Experiment

{"@context":"https://schema.org","@type":"DiscussionForumPosting","headline":"Exceptions slow in 3.11, depending on location","articleBody":"# Bug report\r\n\r\n### Bug description:\r\n\r\n(From [Discourse](https://discuss.python.org/t/why-does-unreached-code-take-linear-time/33295?u=pochmann))\r\n\r\nConsider these two functions:\r\n\r\n```python\r\ndef short():\r\n    try:\r\n        if 0 == 1:\r\n            unreached\r\n        raise RuntimeError\r\n    except RuntimeError:\r\n        pass\r\n\r\ndef long():\r\n    try:\r\n        if 0 == 1:\r\n            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached\r\n            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached\r\n            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached\r\n            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached\r\n            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached\r\n            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached\r\n            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached\r\n            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached\r\n            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached\r\n            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached\r\n        raise RuntimeError\r\n    except RuntimeError:\r\n        pass\r\n```\r\n\r\nThe 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](https://discuss.python.org/t/why-does-unreached-code-take-linear-time/33295/19?u=pochmann)):\r\n\r\n```\r\nPython: 3.11.5 | packaged by conda-forge | (main, Aug 27 2023, 03:34:09) [GCC 12.3.0]\r\n 176.5 ±  0.4 ns  short\r\n 644.7 ±  0.6 ns  long\r\n\r\nPython: 3.10.12 | packaged by conda-forge | (main, Jun 23 2023, 22:40:32) [GCC 12.3.0]\r\n 150.7 ±  0.1 ns  short\r\n 167.0 ±  0.2 ns  long\r\n```\r\n\r\nWhy? Shouldn't it just jump over them all and be just as fast as `short()`?\r\n\r\n\u003cdetails\u003e\u003csummary\u003eBenchmark script\u003c/summary\u003e\r\n\r\n[Attempt This Online!](https://ato.pxeger.com/run?1=7VW9TsMwEB6R_BS3NalCaERBEJSRHbFWVRTac2tBnMi-VFRVn4SlC-y8Ag_BwNNgO0nTMILY6sn-7uf7zsN9L2_lmpaF3O1eK-KnV18nn1wVOZDIURCIvCwUNS-2j7R4iYqns6KShAoy7WJ1lqaMhCYx021ujpkMDD7HFWsgvdaMsTly0Evz9vyYgTmk1vXFHsFhBEkCUQfZU0mF2WyJ8z2qMqER7o0WI-JWqUK5ED7PsKQe3nUqM90qeCrk4lcCbv7_eiQ-Eh-Jj8R_J_7DkuSVNMs8qVd14PalAQsFKQhpGssFeuftAjVdbO6GxzCZgs3iNsv12LoUt_WNSWiP-x0X2aoJwRAivHZ1ZOu0ocS559pO-NSfxBfTaTcUUqVM88HGeoxH2o8vw4hv4eMdNs5wHDZ2mNQwcJU_pEej0YGOvuL-5icjsTZEjwcgq_wBVRKNhsOxD2dG97if3WgOs7JEaWbwWY-gGc3xBPCI68T9yoGWUglJXvtXAfAwTWWWY5rWreq4z1h9Gdw5Q48HgfXXcIVKi0L6tb03Lt-6_Tc)):\r\n\r\n```python\r\nfrom timeit import timeit\r\nfrom time import perf_counter as time\r\nfrom statistics import mean, stdev\r\nimport sys\r\n\r\n\r\ndef short():\r\n    try:\r\n        if 0 == 1:\r\n            unreached\r\n        raise RuntimeError\r\n    except RuntimeError:\r\n        pass\r\n\r\n\r\ndef long():\r\n    try:\r\n        if 0 == 1:\r\n            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached\r\n            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached\r\n            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached\r\n            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached\r\n            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached\r\n            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached\r\n            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached\r\n            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached\r\n            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached\r\n            unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached; unreached\r\n        raise RuntimeError\r\n    except RuntimeError:\r\n        pass\r\n\r\n\r\nfuncs = short, long\r\n\r\nfor _ in range(3):\r\n    times = {f: [] for f in funcs}\r\n    def stats(f):\r\n        ts = [t * 1e9 for t in sorted(times[f])[:5]]\r\n        return f'{mean(ts):6.1f} ± {stdev(ts):4.1f} ns '\r\n    for _ in range(100):\r\n        for f in funcs:\r\n            t = timeit(f, number=10**4) / 1e4\r\n            times[f].append(t)\r\n    for f in sorted(funcs, key=stats):\r\n        print(stats(f), f.__name__)\r\n    print()\r\n\r\nprint('Python:', sys.version)\r\n```\r\n\r\n\u003c/details\u003e\r\n\r\nIn 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`):\r\n```\r\n   100     2.6 μs\r\n  1000    24.3 μs\r\n 10000   253.3 μs\r\n100000  2786.2 μs\r\n```\r\n\r\n\u003cdetails\u003e\u003csummary\u003eBenchmark script\u003c/summary\u003e\r\n\r\n```python\r\nfrom time import perf_counter as time\r\nfrom timeit import repeat\r\n\r\nfor e in range(2, 6):\r\n    n = 10 ** e\r\n    exec(f'''def f():\r\n        if 0 == 1:\r\n            {'unreached;' * n}\r\n        try:\r\n            raise RuntimeError\r\n        except RuntimeError:\r\n            pass''')\r\n    number = 10**6 // n\r\n    t = min(repeat(f, number=number)) / number\r\n    print(f'{n:6} {t * 1e6 :7.1f} μs')\r\n```\r\n\r\n[Attempt This Online!](https://ato.pxeger.com/run?1=fZJNTsMwEIXFNqd4OydRIQ2LgIKy5AJcAIV0TL2IY00cqVWUPXdg0w2cgjOwh9Pg_DRVRGE2tud9Iz0_-_Xd7O220ofDW2Pl5e33RSu5KmFVSVClqdjCEMvHomq0JUZeD5o3U8oeOSZDufU8WTHcsAbn-pn86xWSIPXgSiNDvEYYgoYz7ajwpRBiQxLSn6i-lMQamaNPrb5a0WimvNjS5k4ghO5m2fJ-yXKuasKDs-1c3jNXPMu0K8jYhbacNXldO1vB6Lopn9zNe-thmCCKoIe-da1SaX-8ty9XE5mNSxAgmjoDblhpR4lWp0mH1jr7MSVIb65i2eHzoxbB-AZfL4s4zkRxCuHczvsVxx9R_BtDH8Ho5_g3fgA)\r\n\r\n\u003c/details\u003e\r\n\r\nThe slowness happens when the unreached statements are anywhere before the `raise`, and not when they're anywhere after the `raise` ([demo](https://discuss.python.org/t/why-does-unreached-code-take-linear-time/33295/22?u=pochmann)). So it seems what matters is location of the `raise` in the function. Long code before it somehow makes it slow.\r\n\r\nThis 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.\r\n\r\n\u003cdetails\u003e\u003csummary\u003eBenchmark script with those two solutions and the relevant test case:\u003c/summary\u003e\r\n\r\nThe 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.\r\n\r\nSample times:\r\n```\r\n 664.4 ±  8.6 ns  one_sequential\r\n 762.1 ± 28.8 ns  one_nested\r\n\r\nPython: 3.11.4 (main, Jun 24 2023, 10:18:04) [GCC 13.1.1 20230429]\r\n```\r\n\r\nCode:\r\n\r\n```python\r\nfrom timeit import timeit\r\nfrom statistics import mean, stdev\r\nfrom itertools import repeat, starmap, islice\r\nimport sys\r\n\r\n\r\ndef one_nested(iterable, too_short=None, too_long=None):\r\n    it = iter(iterable)\r\n    for first in it:\r\n        for second in it:\r\n            raise too_long or ValueError(\r\n                'Expected exactly one item in iterable, but',\r\n                f'got {first!r}, {second!r}, and perhaps more.'\r\n            )\r\n        return first\r\n    raise too_short or ValueError('too few items in iterable (expected 1)')\r\n\r\n\r\ndef one_sequential(iterable, too_short=None, too_long=None):\r\n    it = iter(iterable)\r\n\r\n    for first in it:\r\n        break\r\n    else:\r\n        raise too_short or ValueError('too few items in iterable (expected 1)')\r\n\r\n    for second in it:\r\n        raise too_long or ValueError(\r\n            'Expected exactly one item in iterable, but '\r\n            f'got {first!r}, {second!r}, and perhaps more.'\r\n        )\r\n\r\n    return first\r\n\r\n\r\nfuncs = one_nested, one_sequential\r\n\r\ndef empty(f):\r\n    iterable = iter(())\r\n    too_short = RuntimeError()\r\n    for _ in repeat(None, 10**4):\r\n        try:\r\n            f(iterable, too_short)\r\n        except RuntimeError:\r\n            pass\r\n\r\nfor case in empty,:\r\n\r\n    times = {f: [] for f in funcs}\r\n    def stats(f):\r\n        ts = [t * 1e9 for t in sorted(times[f])[:5]]\r\n        return f'{mean(ts):6.1f} ± {stdev(ts):4.1f} ns '\r\n    for _ in range(100):\r\n        for f in funcs:\r\n            t = timeit(lambda: case(f), number=1) / 1e4\r\n            times[f].append(t)\r\n    for f in sorted(funcs, key=stats):\r\n        print(stats(f), f.__name__)\r\n    print()\r\n\r\nprint('Python:', sys.version)\r\n```\r\n\r\n[Attempt This Online!](https://ato.pxeger.com/run?1=rVXNjtMwEL5xyFOYU5IqlEYqCCLluFeEkOBSVZGbjltrE9vYztKo6pNw2QvceQUeg6fBP_ntohWgzSn2zNjfN9_M-Ot30eojZ_f33xpNXrz59ewjkbxGmtZANaK14FJ3q8BZlMaaKk1L1VtrwCwx-3u48y5Ug9ScV4OHBAFYWx8saywSRFVFSwg6s2pVEAR7IIgzKBgoDfvIHoJ3FSTIHFWoo3HM3xm7X1ecHdwyzgJkPoM1d_cOcbHbJ1wiQqUyVJixe-feoKDkbH9tsZ_EVMFwETK-n3DVwI2UXEYzT_uFNycBpQGN4IRLXbWWh0VT-7N7IrtGh8mDaBIeuEZnh_K5vCTo7HG5f2zwCZBHLBSquYRlOIuPh5UE3UjmuQZzCi53VxxCY0AEvjiUagoTRdCzSeMwngij4HMDTFNcPYE4j6uzk4Bv3QoqBeP-k5F6vAT-Xv5_kB7Npftf2TvwM72DgDTMNGQ-aaDkSjOvI9RCtxEZhOnS08kTxb6gxgTn6EPDbPt77mNTFZaf7-vIK5-uFot1PCZRy3beVORPZTNWMJxKEHp23zxeYGXmhL28xEYec79jk2Q-IzbKpuBMMrTZ-tqyTi41F-diM2Dnlxoy4AJt1EajBUrhrYtz9agMOjOH3LEbso032avt9kG_hWc7_iKt4uz1MiUX9POHUdLOQre3dntMdeKPmcPsAFG6WsXzkTQinnO3SvgpHFW43u1x5pJgeCSINfUOZJ7G6KVhsJ7HdeiXWAhghs1kLE5IuhsTdAtt7vIzQSUkZTrqs5YgsiwKhmsoCn-Ut5uq9D_he_eeZGFix_ryDqSinMX-dekemf6x-Q0)\r\n\r\n\u003c/details\u003e\r\n\r\n\r\n### CPython versions tested on:\r\n\r\n3.10, 3.11\r\n\r\n### Operating systems tested on:\r\n\r\nLinux, macOS\n\n\u003c!-- gh-linked-prs --\u003e\n### Linked PRs\n* gh-111548\n* gh-111550\n* gh-111551\n* gh-111948\n* gh-111951\n\u003c!-- /gh-linked-prs --\u003e\n","author":{"url":"https://github.com/pochmann","@type":"Person","name":"pochmann"},"datePublished":"2023-09-09T12:35:57.000Z","interactionStatistic":{"@type":"InteractionCounter","interactionType":"https://schema.org/CommentAction","userInteractionCount":11},"url":"https://github.com/109181/cpython/issues/109181"}