Regression caused by CALL_FUNCTION specialization for C function calls (test_urllib fails when run multiple times)

[vstinner]

BPO	46465
Nosy	@gvanrossum, @vstinner, @markshannon, @ericsnowcurrently, @corona10, @brandtbucher, @sobolevn, @Fidget-Spinner
PRs	bpo-46465: Check eval breaker in specialized CALL opcodes #30826 bpo-46709: check eval breaker in specialized CALL opcodes #31404
Files	bug.py

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = None
created_at = <Date 2022-01-22.01:30:09.079>
labels = ['release-blocker', 'tests', '3.11']
title = 'Regression caused by CALL_FUNCTION specialization for C function calls (test_urllib fails when run multiple times)'
updated_at = <Date 2022-02-18.11:00:24.942>
user = 'https://github.com/vstinner'

bugs.python.org fields:

activity = <Date 2022-02-18.11:00:24.942>
actor = 'sobolevn'
assignee = 'none'
closed = False
closed_date = None
closer = None
components = ['Tests']
creation = <Date 2022-01-22.01:30:09.079>
creator = 'vstinner'
dependencies = []
files = ['50575']
hgrepos = []
issue_num = 46465
keywords = ['patch', '3.11regression']
message_count = 14.0
messages = ['411217', '411219', '411220', '411288', '411348', '411349', '411364', '411366', '411367', '411369', '411370', '411371', '411461', '411652']
nosy_count = 8.0
nosy_names = ['gvanrossum', 'vstinner', 'Mark.Shannon', 'eric.snow', 'corona10', 'brandtbucher', 'sobolevn', 'kj']
pr_nums = ['30826', '31404']
priority = 'release blocker'
resolution = None
stage = 'patch review'
status = 'pending'
superseder = None
type = None
url = 'https://bugs.python.org/issue46465'
versions = ['Python 3.11']

[vstinner]

test_unittest: TestBreakSignalDefault.testInstallHandler() fails if run after TestBreak:
---------

$ ./python -m test -v test_unittest -R 3:3 -m '*TestBreak.testHandlerReplacedButCalled' -m '*TestBreak.testInstallHandler' -m '*TestBreakSignalDefault.testInstallHandler'
(...)
beginning 6 repetitions
123456
testHandlerReplacedButCalled (unittest.test.test_break.TestBreak) ... ok
testInstallHandler (unittest.test.test_break.TestBreak) ... ok
testInstallHandler (unittest.test.test_break.TestBreakSignalDefault) ... ok

---

Ran 3 tests in 0.003s

OK
(...)
.testHandlerReplacedButCalled (unittest.test.test_break.TestBreak) ... ok
testInstallHandler (unittest.test.test_break.TestBreak) ... ok
testInstallHandler (unittest.test.test_break.TestBreakSignalDefault) ... FAIL

======================================================================
FAIL: testInstallHandler (unittest.test.test_break.TestBreakSignalDefault)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/home/vstinner/python/main/Lib/unittest/test/test_break.py", line 38, in testInstallHandler
    self.assertTrue(unittest.signals._interrupt_handler.called)
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
AssertionError: False is not true
(...)

---

Or you can use a "bisect" file:
---
unittest.test.test_break.TestBreak.testHandlerReplacedButCalled
unittest.test.test_break.TestBreak.testInstallHandler
unittest.test.test_break.TestBreakSignalDefault.testInstallHandler
---

And the command:

./python -m test -v -F test_unittest --matchfile=bisect

Or the command:

./python -m test -v test_unittest -R 3:3 --matchfile=bisect

It fails starting at the 4th iteration.

[vstinner]

It's a regression introduced by the following change:

commit 3163e68
Author: Ken Jin <[email protected]>
Date: Wed Oct 20 07:16:36 2021 +0800

bpo-44525: Specialize ``CALL_FUNCTION`` for C function calls (GH-26934)

[vstinner]

Attached bug.py reproduces the bug without unittest, just run:

./python bug.py

On Python 3.10, it writes:
---
LOOP 0
LOOP 1
(...)
LOOP 14
LOOP 15
---

On the main branch, it fails with:
---

LOOP 0
LOOP 1
LOOP 2
LOOP 3
LOOP 4
LOOP 5
LOOP 6
LOOP 7
Traceback (most recent call last):
  File "/home/vstinner/bug.py", line 24, in <module>
    Bug().run()
    ^^^^^^^^^^^
  File "/home/vstinner/bug.py", line 19, in run
    raise Exception("bug")
    ^^^^^^^^^^^^^^^^^^^^^^
Exception: bug

---

[gvanrossum]

@kj, are you looking into this?

[vstinner]

The problem is that the optimization no longer checks for pending signals in TARGET(CALL_NO_KW_BUILTIN_FAST). The patch below fix my issue. I guess that other opcode needs an additional CHECK_EVAL_BREAKER().

diff --git a/Python/ceval.c b/Python/ceval.c
index 9aaddd99eda..7cc0f805366 100644
--- a/Python/ceval.c
+++ b/Python/ceval.c
@@ -4822,6 +4822,7 @@ _PyEval_EvalFrameDefault(PyThreadState *tstate, InterpreterFrame *frame, int thr
                 */
                 goto error;
             }
+            CHECK_EVAL_BREAKER();
             DISPATCH();
         }

[vstinner]

It seems like the following target miss CHECK_EVAL_BREAKER():

TARGET(CALL_NO_KW_METHOD_DESCRIPTOR_FAST) 
TARGET(CALL_NO_KW_METHOD_DESCRIPTOR_O)
TARGET(CALL_NO_KW_BUILTIN_FAST)
TARGET(CALL_NO_KW_BUILTIN_O)
TARGET(CALL_NO_KW_BUILTIN_CLASS_1)

CHECK_EVAL_BREAKER() matters for signals, but also multithreading (drop the GIL), asynchronous exception and pending calls.

[Fidget-Spinner]

Thanks @victor for catching this and figuring it out. I had a hard time narrowing this down since I'm on Windows which doesn't support signals :(.

I'll handle the required patch and tests.

[Fidget-Spinner]

A short summary (thanks to Victor's findings!):

• os.kill(pid, signal.SIGINT) is specialized to CALL_NO_KW_FAST
• CALL_NO_KW_FAST doesn't check eval breaker, so the signal is ignored
• signal handler wasn't called, test fails

I'd like to add tests for some of the other CALL_X in the future, but I'm a little short on time at the moment, sorry! For now, I've tried to turn some of the tests "hot" to see if I can get those to trigger.

[markshannon]

Is this a bug?

Signal handling in Python is asynchronous. https://docs.python.org/3/library/signal.html#execution-of-python-signal-handlers

The example code tests whether the interpreter responds synchronously and immediately.

If you add `for _in range(1): pass` or a call to any Python function in between the `os.kill(pid, SIGNUM)` and the `if not self.called:` then the test passes.

[vstinner]

Is this a bug?

In Python 3.10, the code works. In Python 3.11, it fails.

It's a behavior change. IMO this change is unwanted. I expect that signals are handled "as soon as possible", *especially* if we receive it "during" an os.kill() call on the current process on purpose.

[vstinner]

It's also interesting to note that the implementation of os.kill() and signal.raise_signal() do *not* call PyErr_CheckSignal().

The following signal functions *do* call call PyErr_CheckSignal():

• signal.signal()
• signal.pause()
• signal.pthread_kill()
• signal.pthread_sigmask()

Some other signal functions call PyErr_CheckSignal() if a syscall fails with EINTR (PEP-475).

[vstinner]

Signal handling in Python is asynchronous. https://docs.python.org/3/library/signal.html#execution-of-python-signal-handlers

See my previous comment: "CHECK_EVAL_BREAKER() matters for signals, but also multithreading (drop the GIL), asynchronous exception and pending calls."

If a thread executes a function which only uses opcodes which don't call CHECK_EVAL_BREAKER(), I understand that it can eat more than its slice of 5 ms, see sys.getswitchinterval():
https://docs.python.org/dev/library/sys.html#sys.getswitchinterval

So it's also a threads scheduling issue, no?

[markshannon]

So it's also a threads scheduling issue, no?

No, it isn't. The interpreter checks the eval breaker frequently enough. It checks on all back edges and on all calls to Python functions.

The test probably needs to be fixed, or extended. It is signals sent from another process or thread that we should be testing for.

I'm happy to merge PR 30826, but if you are really concerned about prompt delivery of signals, then you should be worried about C extensions.

If you are worried about being able to interrupt programs, then you also
worry about poorly written Python code that uses `except:`.

Regarding C extensions, I think clear documentation that extension authors need to check for signals in any code that might run for a few hundred microseconds or longer is the best approach.

For `except:`, maybe we could issue a syntax warning, as `except:` is universally considered to be bad practice.

[vstinner]

Regarding C extensions, I think clear documentation that extension authors need to check for signals in any code that might run for a few hundred microseconds or longer is the best approach.

Python 3.10 doesn't require it. If you want to change Python 3.11 behavior, please announce the change on python-dev and capi-sig mailing lists, and document it carefully in What's New in Python 3.11.

I'm not talking about checking frequently interruptions while a function is running, I'm only talking about the "end" of a C function (exit). In Python 3.10, ceval.c does it automatically.

        case TARGET(CALL_FUNCTION): {
            PREDICTED(CALL_FUNCTION);
            PyObject **sp, *res;
            sp = stack_pointer;
            res = call_function(tstate, &trace_info, &sp, oparg, NULL);
            stack_pointer = sp;
            PUSH(res);
            if (res == NULL) {
                goto error;
            }
            CHECK_EVAL_BREAKER();  // <==== HERE
            DISPATCH();
        }

[Fidget-Spinner]

@vstinner this bug is fixed after #31404 right? Can this be closed?

[vstinner]

@vstinner this bug is fixed after #31404 right? Can this be closed?

I wanted to enhance signal.raise_signal(), here is my new PR: #91756

[vstinner]

I confirm that attached bug.py script no longer fails on the current main branch.

Moreover, #90623 (comment) test no longer fails: I ran ./python -m test -v -F test_unittest --matchfile=bisect for 256 iterations (1 minute), it didn't fail.

[vstinner]

I wanted to enhance signal.raise_signal(), here is my new PR: #91756

Merged. I close the issue. Thanks for the ceval.c fix!