Differing behavior for sys.setrace between 3.12 and 3.13

@nedbat

Bug report

Bug description:

def gen():
    print(2)
    yield 3
    print(4)

print(next(gen()))

3.12 events

call 14: def gen():
line 15:     print(2)
line 16:     yield 3
retu 16:     yield 3
call 16:     yield 3
exce 16:     yield 3
retu 16:     yield 3

main:

call 14: def gen():
line 15:     print(2)
line 16:     yield 3
retu 16:     yield 3

Note the extra except and return events for 3.12.

Originally discovered by @nedbat #113680 (comment)

CPython versions tested on:

3.12, 3.13

Operating systems tested on:

No response

This is a sys.monitoring change. sys.settrace merely reflects that.
For

events = []
with record_events(events):
    next(gen())
print(events)

3.12:

['call', 'start', 'call', 'yield', 'raise', 'exception_handled', 'unwind']

3.13:

['call', 'start', 'call', 'yield']

The events for 3.13 look to be correct. The additional 'raise', 'exception_handled', 'unwind' events for 3.12 seem spurious.
Even if 3.13 is now correct we should at the very least document the change.

This has nothing to do with monitoring or tracing. It is about the lifetime of generators.
If we change

with record_events(events):
    next(gen())

to

g = gen()
with record_events(events):
    next(g)

The events recorded are the same for 3.12 and 3.13. The additional events in 3.12 are from the generator being closed.

Bisected to #111069

@nedbat

So what's happening is this:

In 3.12 the generator is closed by calling throw() which causes the 'raise', 'exception_handled', 'unwind' sequence of events.
However, that isn't necessary for a simple generator, so we simply close it in 3.13.

@nedbat is this a problem for coverage?

@markshannon

@markshannon I think this and other sys.monitoring changes are going to require me to do a bit of a re-think. There are tests in the coverage.py test suite that check data based on the raw events. The final user-visible coverage data might come out the same, but the tests are failing now because of changes like this. I'll be working on this.

This isn't a sys.monitoring change.

The change is that we no longer throw into generators to close them.
The events that you were seeing in 3.12 happened in the __del__() method of the generator, which is no longer called in 3.13.

This isn't a sys.monitoring change.

I understand. I meant to say, this and also sys.monitoring changes are changing the way I collect data, and therefore the way I test.

So... There's nothing to see here, move along, and close the issue?

I will re-open if needed.

Investigating other generator tracing failures in the coverage.py test suite, I find that the trace function is invoked slightly differently for the return event when yielding. The frame.last_i value is pointing to YIELD_VALUE in Python 3.12, but points to RESUME in 3.13. Is this intentional? Will it stay this way?

Test program:

import dis, linecache, sys

print(sys.version)

def trace(frame, event, arg):
    # The weird globals here is to avoid a NameError on shutdown...
    if frame.f_code.co_filename == globals().get("__file__"):
        lineno = frame.f_lineno
        line = linecache.getline(__file__, lineno).rstrip()
        print("{} {}: {}".format(event[:4], lineno, line))
    if event == "return":
        code = frame.f_code.co_code
        lasti = frame.f_lasti
        print(f"code[{lasti=}] is {dis.opname[code[lasti]]}")
    return trace

def gen():
    yield 3

dis.dis(gen)

sys.settrace(trace)

print(next(gen()))

Running on 3.12:

3.12.1 (main, Dec  8 2023, 20:58:19) [Clang 15.0.0 (clang-1500.0.40.1)]
 17           0 RETURN_GENERATOR
              2 POP_TOP
              4 RESUME                   0

 18           6 LOAD_CONST               1 (3)
              8 YIELD_VALUE              1
             10 RESUME                   1
             12 POP_TOP
             14 RETURN_CONST             0 (None)
        >>   16 CALL_INTRINSIC_1         3 (INTRINSIC_STOPITERATION_ERROR)
             18 RERAISE                  1
ExceptionTable:
  4 to 14 -> 16 [0] lasti
call 17: def gen():
line 18:     yield 3
retu 18:     yield 3
code[lasti=8] is YIELD_VALUE
call 18:     yield 3
exce 18:     yield 3
retu 18:     yield 3
code[lasti=8] is YIELD_VALUE
3

Running on 3.13.0a2:

3.13.0a2 (main, Nov 24 2023, 14:53:47) [Clang 15.0.0 (clang-1500.0.40.1)]
  17           0 RETURN_GENERATOR
               2 POP_TOP
               4 RESUME                   0

  18           6 LOAD_CONST               1 (3)
               8 YIELD_VALUE              0
              10 RESUME                   5
              12 POP_TOP
              14 RETURN_CONST             0 (None)

None     >>   16 CALL_INTRINSIC_1         3 (INTRINSIC_STOPITERATION_ERROR)
              18 RERAISE                  1
ExceptionTable:
  4 to 14 -> 16 [0] lasti
call 17: def gen():
line 18:     yield 3
retu 18:     yield 3
code[lasti=10] is RESUME
3

Running on the tip of 3.13:

3.13.0a2+ (heads/main:2e17cad2b8, Jan  9 2024, 05:00:41) [Clang 15.0.0 (clang-1500.1.0.2.5)]
  17           RETURN_GENERATOR
               POP_TOP
       L1:     RESUME                   0

  18           LOAD_CONST               1 (3)
               YIELD_VALUE              0
               RESUME                   5
               POP_TOP
               RETURN_CONST             0 (None)

  --   L2:     CALL_INTRINSIC_1         3 (INTRINSIC_STOPITERATION_ERROR)
               RERAISE                  1
ExceptionTable:
  L1 to L2 -> L2 [0] lasti
call 17: def gen():
line 18:     yield 3
retu 18:     yield 3
code[lasti=10] is RESUME
3

@iritkatriel

tl;dr:
Yes, you can rely the semantics of last_i not changing from from now. But we do reserve the right to mess around with the bytecode (although it should be a lot more stable now that PEPs 659 and 669 are done).

Long answer:

The semantics of last_i were less than ideal for 3.11 and 3.12.
Historically (up to 3.10) last_i referred to the last instruction, except when set by frame.f_lineno = and a couple of other corner cases.
In 3.11, some instructions became larger, so that last_i no longer referred to the last instruction, but the last code unit within the last instruction. This meant that the expression dis.opname[code[lasti]] could be gibberish if the previous instruction was a CALL, LOAD_ATTR or other instruction containing more than one code unit.

@iritkatriel fixed all that in #109094 replacing the internal "previous code unit pointer" with a more understandable "instruction pointer". last_i inherits this behavior.
Now the instruction pointer (and last_i) points to the start of the last instruction that started executing, except during a call to a Python function or a send to a generator, when it points to the return/resume address. This is much like an instruction pointer that you might be familiar with from hardware.

@iritkatriel is this summary correct?

Thanks for the detail. It's a bit odd to have f_lasti pointing to the next instruction to execute. I wonder if there's a way to document this? The frame object docs say "the precise instruction", which is ambiguous about next or last.

Now the instruction pointer (and last_i) points to the start of the last instruction that started executing, except during a call to a Python function or a send to a generator, when it points to the return/resume address.

During a call the lasti of the calling frame points to the beginning of the CALL instruction. Same with SEND.

fix: adapt to a 3.13 change in frame.f_lasti

@nedbat

I think this is all sorted.
@nedbat feel to reopen if there is anything else to be done.

Navigation Menu

Repository navigation

Differing behavior for `sys.setrace` between 3.12 and 3.13 #113728

Bug report

Bug description:

CPython versions tested on:

Operating systems tested on:

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Differing behavior for sys.setrace between 3.12 and 3.13 #113728

Description

Bug report

Bug description:

CPython versions tested on:

Operating systems tested on:

Activity

markshannon commented on Jan 5, 2024

markshannon commented on Jan 5, 2024

markshannon commented on Jan 5, 2024

markshannon commented on Jan 5, 2024

nedbat commented on Jan 5, 2024

markshannon commented on Jan 5, 2024

nedbat commented on Jan 5, 2024

gvanrossum commented on Jan 6, 2024

nedbat commented on Jan 6, 2024

nedbat commented on Jan 9, 2024

markshannon commented on Jan 9, 2024

nedbat commented on Jan 9, 2024

iritkatriel commented on Jan 9, 2024

markshannon commented on Jun 18, 2024

Metadata

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Issue actions

Differing behavior for `sys.setrace` between 3.12 and 3.13 #113728