bpo-46344: Fix trace bug in else of try and try-star blocks #30544

iritkatriel · 2022-01-11T17:50:24Z

https://bugs.python.org/issue46344

markshannon · 2022-01-11T18:12:36Z

Lib/test/test_sys_settrace.py

@@ -644,16 +644,22 @@ def func():
                4
            else:
                6
+                if False:


Does this cover the original issue?
The compiler will optimize out the if False.
Might be a good idea to add another test with a non-constant predicate.

The test did fail without the fix. But sure, I'll add a test with a non const.

iritkatriel · 2022-01-11T19:47:40Z

Lib/test/test_dis.py

+  Instruction(opname='RERAISE', opcode=119, arg=0, argval=0, argrepr='', offset=246, starts_line=None, is_jump_target=False, positions=None),
+  Instruction(opname='COPY', opcode=120, arg=3, argval=3, argrepr='', offset=248, starts_line=None, is_jump_target=False, positions=None),
+  Instruction(opname='POP_EXCEPT', opcode=89, arg=None, argval=None, argrepr='', offset=250, starts_line=None, is_jump_target=False, positions=None),
+  Instruction(opname='RERAISE', opcode=119, arg=1, argval=1, argrepr='', offset=252, starts_line=None, is_jump_target=False, positions=None),


There are 9 more opcodes generated now. Looks like that jump enabled some optimisation.

@gvanrossum this PR fixes a regression from the except* PR and it’s all very odd, both the bug and the impact of the fix.

Tracing is Mark's black magic these days (I don't claim to understand the line number table code).

Could it be that test_dis.py wasn't properly regenerated in a while? It's always struck me as odd that there isn't a more direct way to cause this data to be regenerated.

The tests fail if you don’t update it.

I extracted it out of the test. I think with this PR it emits the finally body 4 times, and without it 3 times?

def jumpy(): try: 1 / 0 except ZeroDivisionError: print("Here we go, here we go, here we go...") else: with i as dodgy: print("Never reach this") finally: print("OK, now we're done") import dis dis.dis(jumpy)

Old:

1 0 RESUME 0 2 2 NOP 3 4 LOAD_CONST 1 (1) 6 LOAD_CONST 2 (0) 8 BINARY_OP 11 (/) 10 POP_TOP 12 JUMP_FORWARD 14 (to 42) >> 14 PUSH_EXC_INFO 4 16 LOAD_GLOBAL 0 (ZeroDivisionError) 18 JUMP_IF_NOT_EXC_MATCH 17 (to 34) 20 POP_TOP 5 22 LOAD_GLOBAL 1 (print) 24 LOAD_CONST 3 ('Here we go, here we go, here we go...') 26 CALL_NO_KW 1 28 POP_TOP 30 POP_EXCEPT 32 JUMP_FORWARD 34 (to 102) 4 >> 34 RERAISE 0 >> 36 COPY 3 38 POP_EXCEPT 40 RERAISE 1 7 >> 42 LOAD_GLOBAL 2 (i) 44 BEFORE_WITH 46 STORE_FAST 0 (dodgy) 8 48 LOAD_GLOBAL 1 (print) 50 LOAD_CONST 4 ('Never reach this') 52 CALL_NO_KW 1 54 POP_TOP 7 56 LOAD_CONST 0 (None) 58 DUP_TOP 60 DUP_TOP 62 CALL_NO_KW 3 64 POP_TOP 66 JUMP_FORWARD 11 (to 90) >> 68 PUSH_EXC_INFO 70 WITH_EXCEPT_START 72 POP_JUMP_IF_TRUE 41 (to 82) 74 RERAISE 2 >> 76 COPY 3 78 POP_EXCEPT 80 RERAISE 1 >> 82 POP_TOP 84 POP_EXCEPT 86 POP_TOP 88 POP_TOP 10 >> 90 LOAD_GLOBAL 1 (print) 92 LOAD_CONST 5 ("OK, now we're done") 94 CALL_NO_KW 1 96 POP_TOP 98 LOAD_CONST 0 (None) 100 RETURN_VALUE 5 >> 102 NOP 10 104 LOAD_GLOBAL 1 (print) 106 LOAD_CONST 5 ("OK, now we're done") 108 CALL_NO_KW 1 110 POP_TOP 112 LOAD_CONST 0 (None) 114 RETURN_VALUE >> 116 PUSH_EXC_INFO 118 LOAD_GLOBAL 1 (print) 120 LOAD_CONST 5 ("OK, now we're done") 122 CALL_NO_KW 1 124 POP_TOP 126 RERAISE 0 >> 128 COPY 3 130 POP_EXCEPT 132 RERAISE 1 ExceptionTable: 4 to 10 -> 14 [0] 12 to 12 -> 116 [0] 14 to 28 -> 36 [1] lasti 30 to 32 -> 116 [0] 34 to 34 -> 36 [1] lasti 36 to 44 -> 116 [0] 46 to 54 -> 68 [1] lasti 56 to 66 -> 116 [0] 68 to 74 -> 76 [3] lasti 76 to 80 -> 116 [0] 82 to 82 -> 76 [3] lasti 84 to 88 -> 116 [0] 116 to 126 -> 128 [1] lasti

New:

1 0 RESUME 0 2 2 NOP 3 4 LOAD_CONST 1 (1) 6 LOAD_CONST 2 (0) 8 BINARY_OP 11 (/) 10 POP_TOP 12 JUMP_FORWARD 14 (to 42) >> 14 PUSH_EXC_INFO 4 16 LOAD_GLOBAL 0 (ZeroDivisionError) 18 JUMP_IF_NOT_EXC_MATCH 17 (to 34) 20 POP_TOP 5 22 LOAD_GLOBAL 1 (print) 24 LOAD_CONST 3 ('Here we go, here we go, here we go...') 26 CALL_NO_KW 1 28 POP_TOP 30 POP_EXCEPT 32 JUMP_FORWARD 35 (to 104) 4 >> 34 RERAISE 0 >> 36 COPY 3 38 POP_EXCEPT 40 RERAISE 1 7 >> 42 LOAD_GLOBAL 2 (i) 44 BEFORE_WITH 46 STORE_FAST 0 (dodgy) 8 48 LOAD_GLOBAL 1 (print) 50 LOAD_CONST 4 ('Never reach this') 52 CALL_NO_KW 1 54 POP_TOP 7 56 LOAD_CONST 0 (None) 58 DUP_TOP 60 DUP_TOP 62 CALL_NO_KW 3 64 POP_TOP 66 JUMP_FORWARD 25 (to 118) >> 68 PUSH_EXC_INFO 70 WITH_EXCEPT_START 72 POP_JUMP_IF_TRUE 41 (to 82) 74 RERAISE 2 >> 76 COPY 3 78 POP_EXCEPT 80 RERAISE 1 >> 82 POP_TOP 84 POP_EXCEPT 86 POP_TOP 88 POP_TOP 90 NOP 10 92 LOAD_GLOBAL 1 (print) 94 LOAD_CONST 5 ("OK, now we're done") 96 CALL_NO_KW 1 98 POP_TOP 100 LOAD_CONST 0 (None) 102 RETURN_VALUE 5 >> 104 NOP 10 106 LOAD_GLOBAL 1 (print) 108 LOAD_CONST 5 ("OK, now we're done") 110 CALL_NO_KW 1 112 POP_TOP 114 LOAD_CONST 0 (None) 116 RETURN_VALUE 7 >> 118 NOP 10 120 LOAD_GLOBAL 1 (print) 122 LOAD_CONST 5 ("OK, now we're done") 124 CALL_NO_KW 1 126 POP_TOP 128 LOAD_CONST 0 (None) 130 RETURN_VALUE >> 132 PUSH_EXC_INFO 134 LOAD_GLOBAL 1 (print) 136 LOAD_CONST 5 ("OK, now we're done") 138 CALL_NO_KW 1 140 POP_TOP 142 RERAISE 0 >> 144 COPY 3 146 POP_EXCEPT 148 RERAISE 1 ExceptionTable: 4 to 10 -> 14 [0] 12 to 12 -> 132 [0] 14 to 28 -> 36 [1] lasti 30 to 32 -> 132 [0] 34 to 34 -> 36 [1] lasti 36 to 44 -> 132 [0] 46 to 54 -> 68 [1] lasti 56 to 66 -> 132 [0] 68 to 74 -> 76 [3] lasti 76 to 80 -> 132 [0] 82 to 82 -> 76 [3] lasti 84 to 88 -> 132 [0] 132 to 142 -> 144 [1] lasti

We sometimes duplicate exit blocks to save a jump, but only if they have 4 or fewer instructions.

Maybe the explicit jump prevents that?

I'm going to assume that this is what happened (this jump prevented an inlining optimization), and remove it as in the first version of this PR. This will being us back to where we were before the except* PR was merged.

I think we should probably merge this before the release so that we don’t get a change in behaviour between 3.11a3 and 311.a4.

I agree.
This PR merely highlights the excessive duplication of finally blocks. It doesn't cause it.
Do we have an issue to investigate the cause of finally block duplication?

We do now: link

This reverts commit 46cf04a.

This reverts commit 7ff6500.

This reverts commit beb64bc.

markshannon · 2022-01-13T10:29:58Z

The fix looks good. Just needs that extra test.

iritkatriel · 2022-01-13T10:49:42Z

The fix looks good. Just needs that extra test.

I added yesterday an additional non-const condition to the same test. Is that what you mean?

iritkatriel · 2022-01-13T11:55:34Z

I removed the else from the non-const if statement, so it exactly matches the case in the bpo. I've confirmed again that the test fails on current main branch.

markshannon · 2022-01-13T12:44:41Z

👍

bedevere-bot · 2022-01-13T12:46:07Z

⚠️⚠️⚠️ Buildbot failure ⚠️⚠️⚠️

Hi! The buildbot ARM64 macOS 3.x has failed when building commit 9c2ebb9.

What do you need to do:

Don't panic.
Check the buildbot page in the devguide if you don't know what the buildbots are or how they work.
Go to the page of the buildbot that failed (https://buildbot.python.org/all/#builders/725/builds/714) and take a look at the build logs.
Check if the failure is related to this commit (9c2ebb9) or if it is a false positive.
If the failure is related to this commit, please, reflect that on the issue and make a new Pull Request with a fix.

You can take a look at the buildbot page here:

https://buildbot.python.org/all/#builders/725/builds/714

Summary of the results of the build (if available):

== Tests result: ENV CHANGED ==

411 tests OK.

10 slowest tests:

test_concurrent_futures: 3 min 45 sec
test_multiprocessing_spawn: 2 min 34 sec
test_multiprocessing_forkserver: 1 min 45 sec
test_unparse: 1 min 29 sec
test_asyncio: 1 min 17 sec
test_tokenize: 1 min 17 sec
test_nntplib: 1 min 1 sec
test_lib2to3: 52.5 sec
test_capi: 49.6 sec
test_signal: 46.3 sec

1 test altered the execution environment:
test_ftplib

17 tests skipped:
test_dbm_gnu test_devpoll test_epoll test_gdb test_ioctl
test_msilib test_multiprocessing_fork test_ossaudiodev test_spwd
test_startfile test_tix test_tk test_ttk_guionly test_winconsoleio
test_winreg test_winsound test_zipfile64

Total duration: 9 min 20 sec

Click to see traceback logs

Traceback (most recent call last):
  File "/Users/buildbot/buildarea/3.x.pablogsal-macos-m1.macos-with-brew/build/Lib/asyncore.py", line 90, in read
    obj.handle_read_event()
    ^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/buildbot/buildarea/3.x.pablogsal-macos-m1.macos-with-brew/build/Lib/test/test_ftplib.py", line 384, in handle_read_event
    self._do_ssl_handshake()
    ^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/buildbot/buildarea/3.x.pablogsal-macos-m1.macos-with-brew/build/Lib/test/test_ftplib.py", line 345, in _do_ssl_handshake
    self.socket.do_handshake()
    ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/buildbot/buildarea/3.x.pablogsal-macos-m1.macos-with-brew/build/Lib/ssl.py", line 1346, in do_handshake
    self._sslobj.do_handshake()
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^
ssl.SSLZeroReturnError: TLS/SSL connection has been closed (EOF) (_ssl.c:998)


Traceback (most recent call last):
  File "/Users/buildbot/buildarea/3.x.pablogsal-macos-m1.macos-with-brew/build/Lib/multiprocessing/resource_tracker.py", line 209, in main
    cache[rtype].remove(name)
    ^^^^^^^^^^^^^^^^^^^^^^^^^
KeyError: '/psm_a00172d4'


Traceback (most recent call last):
  File "/Users/buildbot/buildarea/3.x.pablogsal-macos-m1.macos-with-brew/build/Lib/multiprocessing/resource_tracker.py", line 209, in main
    cache[rtype].remove(name)
    ^^^^^^^^^^^^^^^^^^^^^^^^^
KeyError: '/psm_3b110483'


Traceback (most recent call last):
  File "/Users/buildbot/buildarea/3.x.pablogsal-macos-m1.macos-with-brew/build/Lib/threading.py", line 1031, in _bootstrap_inner
    self.run()
    ^^^^^^^^^^
  File "/Users/buildbot/buildarea/3.x.pablogsal-macos-m1.macos-with-brew/build/Lib/test/test_ftplib.py", line 298, in run
    asyncore.loop(timeout=0.1, count=1)
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/buildbot/buildarea/3.x.pablogsal-macos-m1.macos-with-brew/build/Lib/asyncore.py", line 214, in loop
    poll_fun(timeout, map)
    ^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/buildbot/buildarea/3.x.pablogsal-macos-m1.macos-with-brew/build/Lib/asyncore.py", line 157, in poll
    read(obj)
    ^^^^^^^^^
  File "/Users/buildbot/buildarea/3.x.pablogsal-macos-m1.macos-with-brew/build/Lib/asyncore.py", line 94, in read
    obj.handle_error()
    ^^^^^^^^^^^^^^^^^^
  File "/Users/buildbot/buildarea/3.x.pablogsal-macos-m1.macos-with-brew/build/Lib/test/test_ftplib.py", line 421, in handle_error
    raise Exception
    ^^^^^^^^^^^^^^^
Exception
k

bpo-46344: Fix trace bug in else of try and try star blocks

503e79e

iritkatriel requested a review from markshannon as a code owner January 11, 2022 17:50

the-knights-who-say-ni added the CLA signed label Jan 11, 2022

bedevere-bot added the awaiting core review label Jan 11, 2022

iritkatriel added the skip news label Jan 11, 2022

markshannon reviewed Jan 11, 2022

View reviewed changes

iritkatriel added 2 commits January 11, 2022 18:39

add non-const predicate to test

87c25b1

fix test_dis

46cf04a

iritkatriel force-pushed the bpo-46344-tracebug branch from 77a1602 to 46cf04a Compare January 11, 2022 19:43

iritkatriel commented Jan 11, 2022

View reviewed changes

iritkatriel added 4 commits January 12, 2022 13:06

put back the JUMP_FORWARDS and add UNSET_LOC to fix the trace

beb64bc

Revert "fix test_dis"

7ff6500

This reverts commit 46cf04a.

Revert "Revert "fix test_dis""

43aefd2

This reverts commit 7ff6500.

Revert "put back the JUMP_FORWARDS and add UNSET_LOC to fix the trace"

aac20fa

This reverts commit beb64bc.

iritkatriel mentioned this pull request Jan 13, 2022

Understand try-finally code generation and reduce duplication of finally blocks faster-cpython/ideas#221

Closed

remove else from condition in test

d95af87

iritkatriel merged commit 9c2ebb9 into python:main Jan 13, 2022

bedevere-bot removed the awaiting core review label Jan 13, 2022

iritkatriel deleted the bpo-46344-tracebug branch January 13, 2022 15:32

Uh oh!

bpo-46344: Fix trace bug in else of try and try-star blocks #30544

bpo-46344: Fix trace bug in else of try and try-star blocks #30544

Uh oh!

Conversation

iritkatriel commented Jan 11, 2022 • edited by bedevere-bot Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

iritkatriel Jan 13, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

markshannon commented Jan 13, 2022

Uh oh!

iritkatriel commented Jan 13, 2022

Uh oh!

iritkatriel commented Jan 13, 2022

Uh oh!

markshannon commented Jan 13, 2022

Uh oh!

bedevere-bot commented Jan 13, 2022

⚠️⚠️⚠️ Buildbot failure ⚠️⚠️⚠️

Uh oh!

Uh oh!

iritkatriel commented Jan 11, 2022 •

edited by bedevere-bot

Loading

iritkatriel Jan 13, 2022 •

edited

Loading