classification
Title: Python 3.8 changes how returns through finally clauses are traced
Type: behavior Stage: resolved
Components: Interpreter Core Versions: Python 3.8
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: Mark.Shannon, nedbat, serhiy.storchaka
Priority: normal Keywords:

Created on 2018-09-16 13:15 by nedbat, last changed 2021-01-13 16:20 by Mark.Shannon. This issue is now closed.

Messages (9)
msg325484 - (view) Author: Ned Batchelder (nedbat) * (Python triager) Date: 2018-09-16 13:15
When a return statement also executes a finally clause, the sequence of lines reported to the trace function is different in 3.8 than it has been before 3.8:

$ cat finally_trace.py
def return_from_finally():
    try:
        print("returning")
        return 17
    finally:
        print("finally")

def trace(frame, event, arg):
    print(frame.f_lineno, event)
    return trace

import sys
sys.settrace(trace)
return_from_finally()

$ python3.7 finally_trace.py
1 call
2 line
3 line
returning
4 line
6 line
finally
6 return

$ python3.8 finally_trace.py
1 call
2 line
3 line
returning
4 line
6 line
finally
4 line
4 return


Is this intentional? Is it a bug? Will it change back before 3.8 is shipped?
msg325485 - (view) Author: Ned Batchelder (nedbat) * (Python triager) Date: 2018-09-16 13:16
This affects coverage.py, as reported in this bug: https://github.com/nedbat/coveragepy/issues/707
msg325489 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2018-09-16 14:28
This is a side effect of specific optimization. If the return value is constant, it is pushed on the stack after executing the finally code (see LOAD_CONST at offset 14 below). But other opcodes at this line (POP_BLOCK and CALL_FINALLY) are executed after executing the finally code. Thus it looks like the line 4 is executed twice, but actually different opcodes marked with the same line are executed before and after executing the finally code.

Disassembly of <code object return_from_finally at 0x7feff78897c0, file "<stdin>", line 1>:
  2           0 SETUP_FINALLY           16 (to 18)

  3           2 LOAD_GLOBAL              0 (print)
              4 LOAD_CONST               1 ('returning')
              6 CALL_FUNCTION            1
              8 POP_TOP

  4          10 POP_BLOCK
             12 CALL_FINALLY             4 (to 18)
             14 LOAD_CONST               2 (17)
             16 RETURN_VALUE

  6     >>   18 LOAD_GLOBAL              0 (print)
             20 LOAD_CONST               3 ('finally')
             22 CALL_FUNCTION            1
             24 POP_TOP
             26 END_FINALLY
             28 LOAD_CONST               0 (None)
             30 RETURN_VALUE

The benefit of this optimization is that it can make the stack smaller. This decreases the memory consumption of the Python function frame by one pointer and speeds up the Python function frame creation time (one pointer assignment less). It is tiny, but I think it is worth to keep it.

I don't know what is the right solution here.
msg325490 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2018-09-16 14:39
Humm, the optimization is not related here. Even if it is not involved (replace 17 with []), the line 4 is reported twice, because RETURN_VALUE is executed after CALL_FINALLY.

  4          10 BUILD_LIST               0
             12 POP_BLOCK
             14 CALL_FINALLY             2 (to 18)
             16 RETURN_VALUE

In 3.7 RETURN_VALUE was the opcode executed at line 4. The stack of blocks was unwinded at interpreted loop implicitly when execute RETURN_VALUE. But in 3.8 calling the finally code is explicit.
msg326180 - (view) Author: Ned Batchelder (nedbat) * (Python triager) Date: 2018-09-23 20:36
I can't tell if you think this is something that should be fixed, or not? (Also, I'm not getting email notifications from bpo, sorry for the delay).
msg326185 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2018-09-23 21:22
I think that this can be fixed. But this is not easy.
msg326215 - (view) Author: Mark Shannon (Mark.Shannon) * (Python committer) Date: 2018-09-24 09:58
The new behaviour looks the more correct to me.

Arguably the sequence should not include the second "4 line", but is otherwise correct.
msg326216 - (view) Author: Mark Shannon (Mark.Shannon) * (Python committer) Date: 2018-09-24 10:01
When I get a chance I'll see what happens with https://github.com/python/cpython/pull/6641
msg385047 - (view) Author: Mark Shannon (Mark.Shannon) * (Python committer) Date: 2021-01-13 16:20
In master, the sequence of events is:

1 call
2 line
3 line
returning
4 line
6 line
finally
6 return

which is the same as 3.7.
I now believe this is the correct trace, as the language spec states:

When a return, break or continue statement is executed in the try suite of a try…finally statement, the finally clause is also executed ‘on the way out.’

So line 6 should be last line traced.
History
Date User Action Args
2021-01-13 16:20:06Mark.Shannonsetstatus: open -> closed
resolution: fixed
messages: + msg385047

stage: resolved
2018-09-24 10:01:02Mark.Shannonsetmessages: + msg326216
2018-09-24 09:58:41Mark.Shannonsetmessages: + msg326215
2018-09-23 21:22:26serhiy.storchakasetmessages: + msg326185
2018-09-23 20:36:22nedbatsetmessages: + msg326180
2018-09-16 14:39:02serhiy.storchakasetnosy: + Mark.Shannon
messages: + msg325490
2018-09-16 14:28:56serhiy.storchakasetnosy: + serhiy.storchaka
messages: + msg325489
2018-09-16 13:16:53nedbatsetmessages: + msg325485
2018-09-16 13:15:56nedbatcreate