Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Traceback says line -1 when KeyboardInterrupt during minimal for-if-loop #107901

Open
pan324 opened this issue Aug 12, 2023 · 14 comments
Open

Traceback says line -1 when KeyboardInterrupt during minimal for-if-loop #107901

pan324 opened this issue Aug 12, 2023 · 14 comments
Assignees
Labels
3.11 bug and security fixes 3.12 bugs and security fixes 3.13 new features, bugs and security fixes type-bug An unexpected behavior, bug, or error

Comments

@pan324
Copy link
Contributor

pan324 commented Aug 12, 2023

More generally, the issue happens with all exceptions raised by other threads.

Run the code below and interrupt with ctrl+c.

# If part of a file, potentially more code before the loop. Traceback says -1 regardless.
for i in range(30000000):
  if not i%1000000:
      pass  # Or any other operation here that is faster than iterating a million i values.

With the following traceback:

Traceback (most recent call last):
 File "/home/panta/issue.py", line -1, in <module>
KeyboardInterrupt

The issue disappears as soon as we add just a bit more to the loop

for i in range(30000000):
  if not i%1000000:  # The 3.10 traceback points to this line.
      pass
  pass  # The 3.11 and 3.12 tracebacks point to this line.
Traceback (most recent call last):
File "/home/panta/issue.py", line 4, in <module>
  pass
KeyboardInterrupt

The issue persists whether running from the shell or as a file or even using exec. It works the same inside functions/methods. It exists in 3.11 and 3.12 but not 3.10, across Windows and Linux.

  • CPython versions tested on: 3.10.6 (no issue), 3.11.1 (issue), 3.11.4 (issue), 3.12.0rc1 (issue)
  • Operating system and architecture: Windows 10 and Ubuntu 22.04.2 LTS (WSL)

Linked PRs

@pan324 pan324 added the type-bug An unexpected behavior, bug, or error label Aug 12, 2023
@Eclips4 Eclips4 added 3.11 bug and security fixes 3.12 bugs and security fixes 3.13 new features, bugs and security fixes labels Aug 12, 2023
@sunmy2019
Copy link
Member

@markshannon as an expert here.

I investigated the -1 being set at Line 950 here.

static void
advance(PyCodeAddressRange *bounds)
{
ASSERT_VALID_BOUNDS(bounds);
bounds->opaque.computed_line += get_line_delta(bounds->opaque.lo_next);
if (is_no_line_marker(*bounds->opaque.lo_next)) {
bounds->ar_line = -1;
}
else {
bounds->ar_line = bounds->opaque.computed_line;
}
bounds->ar_start = bounds->ar_end;

-1 set at

*bounds = {ar_start = 42, ar_end = 46, ar_line = -1, opaque = {computed_line = 2, lo_next = ... , limit = ""}}

during the call of

_PyCode_CheckLineNumber (lasti=42, bounds=...)

Also the disassembly here:

  0           0 RESUME                   0

  1           2 LOAD_NAME                0 (range)
              4 PUSH_NULL
              6 LOAD_CONST               0 (30000000000000)
              8 CALL                     1
             16 GET_ITER
        >>   18 FOR_ITER                14 (to 50)
             22 STORE_NAME               1 (i)

  2          24 LOAD_NAME                1 (i)
             26 LOAD_CONST               1 (1000000)
             28 BINARY_OP                6 (%)
             32 TO_BOOL
             40 POP_JUMP_IF_FALSE        2 (to 46)
             42 JUMP_BACKWARD           14 (to 18)

  3     >>   46 JUMP_BACKWARD           16 (to 18)

  1     >>   50 END_FOR
             52 RETURN_CONST             2 (None)

@sweeneyde
Copy link
Member

cc @iritkatriel as well. I bisected to 4c72517, and I think this is the relevant line:

basicblock_addop(backwards_jump, JUMP, target->b_label.id, NO_LOCATION);

I assume we need every instruction that checks the eval breaker to also have a line number. It looks like propagate_line_numbers and duplicate_exits_without_lineno try to enforce something like this, but then normalize_jumps re-introduces an instruction with NO_LOCATION.

Here's the disassembly showing a JUMP_BACKWARD with Positions(lineno=None, end_lineno=None, col_offset=None, end_col_offset=None):

Disassembly of reproducer on main.
def f():
    for i in range(30000000):
        if not i%1000000:
            pass

import dis
from pprint import pprint
pprint(list(dis.get_instructions(f)))
[Instruction(opname='RESUME', opcode=151, arg=0, argval=0, argrepr='', offset=0, start_offset=0, starts_line=1, is_jump_target=False, positions=Positions(lineno=1, end_lineno=1, col_offset=0, end_col_offset=0)),
 Instruction(opname='LOAD_GLOBAL', opcode=116, arg=1, argval='range', argrepr='range + NULL', offset=2, start_offset=2, starts_line=2, is_jump_target=False, positions=Positions(lineno=2, end_lineno=2, col_offset=13, end_col_offset=18)),
 Instruction(opname='LOAD_CONST', opcode=100, arg=1, argval=30000000, argrepr='30000000', offset=12, start_offset=12, starts_line=None, is_jump_target=False, positions=Positions(lineno=2, end_lineno=2, col_offset=19, end_col_offset=27)),
 Instruction(opname='CALL', opcode=171, arg=1, argval=1, argrepr='', offset=14, start_offset=14, starts_line=None, is_jump_target=False, positions=Positions(lineno=2, end_lineno=2, col_offset=13, end_col_offset=28)),
 Instruction(opname='GET_ITER', opcode=68, arg=None, argval=None, argrepr='', offset=22, start_offset=22, starts_line=None, is_jump_target=False, positions=Positions(lineno=2, end_lineno=4, col_offset=4, end_col_offset=16)),
 Instruction(opname='FOR_ITER', opcode=93, arg=14, argval=56, argrepr='to 56', offset=24, start_offset=24, starts_line=None, is_jump_target=True, positions=Positions(lineno=2, end_lineno=4, col_offset=4, end_col_offset=16)),
 Instruction(opname='STORE_FAST', opcode=125, arg=0, argval='i', argrepr='i', offset=28, start_offset=28, starts_line=None, is_jump_target=False, positions=Positions(lineno=2, end_lineno=2, col_offset=8, end_col_offset=9)),
 Instruction(opname='LOAD_FAST', opcode=124, arg=0, argval='i', argrepr='i', offset=30, start_offset=30, starts_line=3, is_jump_target=False, positions=Positions(lineno=3, end_lineno=3, col_offset=15, end_col_offset=16)),
 Instruction(opname='LOAD_CONST', opcode=100, arg=2, argval=1000000, argrepr='1000000', offset=32, start_offset=32, starts_line=None, is_jump_target=False, positions=Positions(lineno=3, end_lineno=3, col_offset=17, end_col_offset=24)),
 Instruction(opname='BINARY_OP', opcode=122, arg=6, argval=6, argrepr='%', offset=34, start_offset=34, starts_line=None, is_jump_target=False, positions=Positions(lineno=3, end_lineno=3, col_offset=15, end_col_offset=24)),
 Instruction(opname='TO_BOOL', opcode=6, arg=None, argval=None, argrepr='', offset=38, start_offset=38, starts_line=None, is_jump_target=False, positions=Positions(lineno=3, end_lineno=3, col_offset=15, end_col_offset=24)),
 Instruction(opname='POP_JUMP_IF_FALSE', opcode=114, arg=2, argval=52, argrepr='to 52', offset=46, start_offset=46, starts_line=None, is_jump_target=False, positions=Positions(lineno=3, end_lineno=3, col_offset=15, end_col_offset=24)),
 Instruction(opname='JUMP_BACKWARD', opcode=140, arg=14, argval=24, argrepr='to 24', offset=48, start_offset=48, starts_line=None, is_jump_target=False, positions=Positions(lineno=None, end_lineno=None, col_offset=None, end_col_offset=None)),
 Instruction(opname='JUMP_BACKWARD', opcode=140, arg=16, argval=24, argrepr='to 24', offset=52, start_offset=52, starts_line=4, is_jump_target=True, positions=Positions(lineno=4, end_lineno=4, col_offset=12, end_col_offset=16)),
 Instruction(opname='END_FOR', opcode=4, arg=None, argval=None, argrepr='', offset=56, start_offset=56, starts_line=2, is_jump_target=True, positions=Positions(lineno=2, end_lineno=4, col_offset=4, end_col_offset=16)),
 Instruction(opname='RETURN_CONST', opcode=121, arg=0, argval=None, argrepr='None', offset=58, start_offset=58, starts_line=None, is_jump_target=False, positions=Positions(lineno=2, end_lineno=4, col_offset=4, end_col_offset=16))]

@pan324
Copy link
Contributor Author

pan324 commented Aug 13, 2023

In case this helps with debugging, I've played around a bit more and found an even simpler test case:

for i in q:  # Where q = [1]*int(3e7) or something similar.
    if i:
        pass

@sunmy2019
Copy link
Member

I assume we need every instruction that checks the eval breaker to also have a line number.

Agree.

@iritkatriel
Copy link
Member

I bisected to 4c72517, and I think this is the relevant line:

basicblock_addop(backwards_jump, JUMP, target->b_label.id, NO_LOCATION);

Looks plausible. It might be simply a matter of copying the location of the old (backward jump) to the new jump that we are adding in this line. Let me know if you would like to try, or would prefer I do.

@markshannon
Copy link
Member

Does the insertion of the extra jump take place before or after line number propagation?
If it happens before, then simply copying the line number may not be insufficient, as the original jump may not have a line number.

@markshannon
Copy link
Member

This also happens in 3.11, which suggests that 4c72517 is not the root cause.
I think line number propagation (or the lack of) is the issue.

For the fix in 3.13 we might want to tag instructions that check the eval breaker (as well as raises and returns) as needing a line number, then make sure we propagate line numbers to those instructions.

For the 3.11 and 3.12 maybe just backport the change to line propagation and not the metadata?

@iritkatriel
Copy link
Member

Does the insertion of the extra jump take place before or after line number propagation?
If it happens before, then simply copying the line number may not be insufficient, as the original jump may not have a line number.

It happens after line numbers are resolved.

@iritkatriel
Copy link
Member

I created a PR that fixes the case that was reported here.

We will need to follow up with tests that ensure that all instructions that check the eval breaker have a line number. I tested and found that this is not the case, I saw some instructions in exception handlers that violated this (and they were not as straightforward to fix).

miss-islington pushed a commit to miss-islington/cpython that referenced this issue Aug 22, 2023
…of a for loop (pythonGH-108242)

(cherry picked from commit a1cc74c)

Co-authored-by: Irit Katriel <1055913+iritkatriel@users.noreply.github.com>
Yhg1s pushed a commit that referenced this issue Aug 22, 2023
… of a for loop (GH-108242) (#108275)

gh-107901: Fix missing line number on BACKWARD_JUMP at the end of a for loop (GH-108242)
(cherry picked from commit a1cc74c)

Co-authored-by: Irit Katriel <1055913+iritkatriel@users.noreply.github.com>
@iritkatriel
Copy link
Member

I've pushed a fix for 3.12 and main. In 3.11 this is a different problem - the JUMP transformation that needed fixing is not there. The bytecode looks like this:

3           0 RESUME                   0

4           2 LOAD_GLOBAL              1 (NULL + range)
           14 LOAD_CONST               1 (30000000)
           16 PRECALL                  1
           20 CALL                     1
           30 GET_ITER
      >>   32 FOR_ITER                 7 (to 48)
           34 STORE_FAST               0 (i)

5          36 LOAD_FAST                0 (i)
           38 LOAD_CONST               2 (1000000)
           40 BINARY_OP                6 (%)
           44 POP_JUMP_FORWARD_IF_TRUE     0 (to 46)

6     >>   46 JUMP_BACKWARD            8 (to 32)

4     >>   48 LOAD_CONST               0 (None)
           50 RETURN_VALUE

You would have thought that the jump in line 44 would be removed as redundant, but it's not for some reason. Anyway, the problem is that the JUMP_BACKWARD doesn't have a line number. Since it's part of the for loop, I think we can give it the line number of the FOR_ITER because that's the next instruction that is going to be executed anyway.

@iritkatriel
Copy link
Member

I made a PR for 3.11 with the equivalent fix, but in that case it had impact on line tracing (I'm not sure why in 3.12 and main it didn't, but @markshannon might).

The line trace in 3.11 ends up showing the line of the FOR_ITER statement being executed twice on every loop except the first (once for the JUMP_BACKWARDS, and once for the FOR_ITER). I think this makes the trace wrong (always) for the sake of getting the line number right in a pretty esoteric case. Not sure it's worth it.

@gvanrossum
Copy link
Member

Presumably the difference between 3.11 and 3.12 is PEP 669 (instrumentation). I agree that a fix that duplicates trace events is worse than not fixing it. And I'm not sure how much effort we should spend at this point to come up with a correct fix unique to 3.11.

@hugovk
Copy link
Member

hugovk commented Nov 9, 2023

Can this issue be closed or is there more to do?

@iritkatriel
Copy link
Member

Still need to do this:

We will need to follow up with tests that ensure that all instructions that check the eval breaker have a line number. I tested and found that this is not the case, I saw some instructions in exception handlers that violated this (and they were not as straightforward to fix).

iritkatriel added a commit to iritkatriel/cpython that referenced this issue Jan 4, 2024
iritkatriel added a commit to iritkatriel/cpython that referenced this issue Jan 4, 2024
iritkatriel added a commit to iritkatriel/cpython that referenced this issue Jan 4, 2024
iritkatriel added a commit that referenced this issue Jan 6, 2024
iritkatriel added a commit to iritkatriel/cpython that referenced this issue Jan 11, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
3.11 bug and security fixes 3.12 bugs and security fixes 3.13 new features, bugs and security fixes type-bug An unexpected behavior, bug, or error
Projects
None yet
Development

No branches or pull requests

8 participants