Skip to content

Tier 2 corrupts frame locals when a sys.monitoring tool is active (3.14) #156319

Description

@BwL1289

Tier 2 corrupts frame locals when a sys.monitoring tool is active (3.14)

Running a large pytest suite under coverage.py on 3.14 with the experimental JIT enabled, a plain attribute store in unittest/mock.py starts raising exceptions that cannot come from that bytecode. Roughly 530 of 1180 tests fail this way.

The line is MagicProxy.__init__:

class MagicProxy(Base):
    def __init__(self, name, parent):
        self.name = name          # line 2260
        self.parent = parent

Across runs of the same suite, that one line produces three different exceptions:

TypeError: '>' not supported between instances of 'MagicProxy' and 'int'
NameError: name 'name' is not defined
AttributeError: 'MagicProxy' object has no attribute 'name'

The NameError is for name, which is a bound parameter of the function. There is no > anywhere on that line, in that function, or in anything it calls. Three different exception types out of one attribute store looks like the frame's locals are being read from the wrong state rather than like any single bad value.

One detail that may or may not be a coincidence: mock.py contains exactly two comparisons against an int literal. One of them is line 761, if len(_name_list) > 1:, inside _extract_mock_name, which __repr__ calls and which is very hot in this workload. That
comparison would produce exactly the '>' not supported ... and 'int' message we see. We have not proven a connection, but it is the only source of that message in the file.

Since construction aborts halfway, the output is also full of AttributeError('_mock_methods') raised in repr().

Trigger:

Two things have to be true at once and neither on its own does anything.

The first is an active sys.monitoring tool. In our case that is coverage.py's default sysmon core, which registers a global PY_START event across the whole process and then attaches local LINE events to the files being measured. We confirmed this by reading sys.monitoring.get_events() at the moment of a failure. Worth noting that the corrupted code (unittest/mock.py) is not one of the measured files, and has no local events on it. The global PY_START registration is presumably why it is affected anyway.

The second is enough hot Python running in the process. Failures never appear at the start of a run. The first 86 tests always pass, then failures arrive in long contiguous blocks with equally long clean stretches between them, which suggests it is per code object rather than a global corruption.

Failure counts scale with how much work each worker process does:

pytest -v --cov, no xdist                    533 failed
pytest -v --cov -n 1                         509 to 533 failed
pytest -v --cov -n auto (20 workers)         6 failed
pytest -q --cov                              0
pytest -v, no --cov                          0
pytest -v --cov, COVERAGE_CORE=ctrace        0

There is nothing special about -v beyond the fact that it runs more Python in pytest's reporting path. pytest-xdist is not needed; it reproduces in a single process.

What the trace log shows

We patched Python/optimizer.c so DPRINTF/PYTHON_LLTRACE compile in a release build (a --with-pydebug build flips the ABI tag to cp314d and none of the installed extensions import), then dumped every trace projection.

Three things came out of that, and together they are the most useful evidence we have.

First, at the moment of the first failure only 71 traces have been projected in the whole process, and not one of them is in unittest/mock.py. Neither _mock_set_magics nor _extract_mock_name has an executor yet. Everything traced so far is import and collection machinery: importlib.metadata, pathlib, functools, execnet, pytest's assertion rewriter, pydantic, re, email, inspect. So the function that blows up has no executor of its own when it blows up.

Second, no trace contains a single _PUSH_FRAME. Nothing is being inlined, so this is not a case of some other function's trace running inlined inside MagicProxy.__init__.

Third, and this seems like the important one: in the failing frame the local is bound. pytest prints frame locals alongside the traceback, and for the NameError run it shows

self = <unittest.mock.MagicProxy object at 0xff5aaea0c2f0>, name = '__delitem__'
...
/usr/local/lib/python3.14/unittest/mock.py:2260: NameError

name holds '__delitem__' in f_locals, and the same line raised NameError: name 'name' is not defined. The frame's locals array is fine. Whatever executed against it read the wrong slot. That reads more like the wrong instruction stream running against a correct frame than like corrupted data.

For contrast, we also built a reproducer that projects 6202 traces of _mock_set_magics alone, nearly 900 times more than the real run, and it never fails. Sheer volume of tracing on the affected function is clearly not what does it.

What we ruled out

We rebuilt CPython several ways against the same suite to narrow this down.

what we suspected how we tested it result
our unusual build flags rebuilt at stock -O2, dropping Polly, ThinLTO, --icf=all, tail-call interp, --enable-safety and PGO still fails, 548
a compiler bug rebuilt at -O0 still fails, 544
the machine code JIT or its stencils --enable-experimental-jit=interpreter, so uops run in the interpreter and no machine code is generated still fails, 537
already fixed upstream 3.14.2, 3.14.6, 3.14.7 and the 3.14 branch tip all fail
coverage.py itself COVERAGE_CORE=ctrace, the classic C trace function clean
tier 2 being involved at all JIT compiled out entirely clean
an invariant we could catch built with --with-assertions reproduces, and no assertion fires

So this is not our compiler and not our build options, and it is not the machine code generation either, since the tier 2 interpreter alone is enough. The assertions build is maybe the most useful data point: whatever goes wrong does not violate anything CPython
currently checks for.

Environment

CPython 3.14.6, also reproduced on 3.14.2, 3.14.7 and the 3.14 branch tip, all configured with --enable-experimental-jit. aarch64 Linux on Graviton, clang. coverage.py 7.15.4, pytest 9.1.1, pytest-cov 7.1.0.

Root cause

We tracked this down with C level probes in the interpreter, which is safe here where Python level instrumentation is not: tier 2 warmup counters count Python bytecodes, so a printf in C does not move which functions get optimised.

First, the failing frame's instr_ptr is garbage. A probe in _PyEval_FormatExcCheckArg printing the executing frame at every NameError gave 544 identical rows on a 544 failure run:

name=name  qual=MagicProxy.__init__  size=15  lasti=-1781584847  in_range=0

MagicProxy.__init__ is 15 code units long and its instruction pointer is sitting about 1.8 billion units before the start of its own bytecode. Every unrelated NameError in the same run has a sane in range value, so this is specific, and identical every time, so it is not random.

Second, we caught the write. Validating every tier 2 _SET_IP against the current frame's code object gave 533 bad writes on a 533 failure run, a 1 to 1 match:

frame_qual=MagicProxy.__init__  frame_size=15  off=-1781584847
exec_code_qual=MagicMixin._mock_set_magics  uop_index=26

Third, the trace itself shows what happened:

20 _SET_IP                     operand0=0xaad97595e63e   caller's code region
21 _CHECK_AND_ALLOCATE_OBJECT  oparg=2  operand0=0x2552b
22 _CREATE_INIT_FRAME          oparg=2
23 _PUSH_FRAME                 oparg=2                   frame becomes MagicProxy.__init__
24 _CHECK_VALIDITY
25 _TIER2_RESUME_CHECK
26 _SET_IP                     operand0=0xffca440536c2   different memory region
27 _LOAD_GLOBAL                oparg=1

MagicProxy.__init__ is self.name = name; self.parent = parent. It contains no LOAD_GLOBAL. So after _PUSH_FRAME switches to the callee, the trace carries on executing some other function's inlined body.

We checked whether the runtime guard was at fault, and it is not. Probing _CHECK_AND_ALLOCATE_OBJECT shows it doing the right thing:

tp_name=MagicProxy  tp_version=152875  guard_version=152875
init_code_qual=MagicProxy.__init__

Right class, matching version, and _spec_cache.init really is MagicProxy.__init__. The frame that gets pushed is correct. It is the trace that was built wrong.

Which brings us to what we think is the actual bug. In Python/specialize.c, specialising a call to a simple class writes a TYPE version into the call cache:

unsigned int tp_version = 0;
PyObject *init = get_init_for_simple_managed_python_class(tp, &tp_version);
if (init != NULL && _PyType_CacheInitForSpecialization((PyHeapTypeObject *)tp, init, tp_version)) {
    _PyCallCache *cache = (_PyCallCache *)(instr + 1);
    write_u32(cache->func_version, tp_version);
    specialize(instr, CALL_ALLOC_AND_ENTER_INIT);

and in Python/optimizer.c, translate_bytecode_to_trace reads that same field back as a FUNCTION version when deciding what to inline at _PUSH_FRAME:

uint32_t func_version = read_u32(&instr[func_version_offset].cache);
PyFunctionObject *new_func = _PyFunction_LookupByVersion(func_version, (PyObject **)&new_code);

For CALL_ALLOC_AND_ENTER_INIT that number is a type version, so the lookup can return an unrelated function that happens to share the value, and the projector inlines that function's bytecode. Note that 152875 is 0x2552b, the operand on _CHECK_AND_ALLOCATE_OBJECT in the trace above, which is how we tied the two halves together.

This also explains why the workload matters so much. Whether the numbers collide depends on the exact order type and function versions are handed out. unittest.mock creates a fresh heap type for every MagicMock() (NonCallableMock.__new__), so this suite burns through an enormous number of type versions and a collision becomes likely, while a small script never allocates
enough to collide.

A fix that works

Adding CALL_ALLOC_AND_ENTER_INIT to the bail list the projector already has for calls whose callee it cannot resolve:

if (opcode == CALL_ALLOC_AND_ENTER_INIT) {
    /* This specialization stores a TYPE version in cache->func_version, so
     * resolving it with _PyFunction_LookupByVersion can return an unrelated
     * function that happens to share the number. */
    DPRINTF(2, "Bailing: CALL_ALLOC_AND_ENTER_INIT caches a type version\n");
    OPT_STAT_INC(unknown_callee);
    return 0;
}

With that patch, JIT enabled, coverage on the sysmon core, and the same -v run that previously failed 509 to 544 tests: 1158 passed, 0 failed, coverage 95.75%.

We are not proposing this as the right fix. It gives up an optimisation rather than resolving the callee properly, and the better repair is presumably to look the init up through the type's _spec_cache.init, or to verify the identity of the code object the trace is about to inline. We also have not run CPython's own test suite against it. We are offering it as confirmation that the diagnosis is correct.

Why we think it resists minimisation

The failure count responds continuously to tiny changes in how much Python runs, which we think is the single most useful thing we can tell you. Same suite, same interpreter, same flags otherwise:

baseline                                                    509, 533, 509 failed
-p plugin defining a no-op pytest_collection_modifyitems    257, 298 failed
same plugin, hook body also does os.environ.get() + int()   0 failed
-q instead of -v                                            0 failed
COVERAGE_CORE=ctrace                                        0 failed
an empty plugin with no hooks                               509 failed (no effect)
an extra directory on PYTHONPATH                            533 failed (no effect)

Each configuration is stable across repeat runs, so this is not flakiness, it is a dose response. A hook that does nothing at all halves the failure count. Two more lines of work inside that hook takes it to zero.

That is presumably why we cannot build a small reproducer: there does not seem to be a list of ingredients to assemble, the workload has to sit on a particular edge, and anything we add to observe it pushes it off. It also means anyone trying to reproduce this from a synthetic script is likely to conclude, wrongly, that there is nothing there.

We could not reduce this to a small script. Nine attempts all failed to reproduce: mock construction in a tight loop (30k iterations), the same under coverage run (18k), an eight thread version (128k), local LINE events returning DISABLE on generated code objects (81k), a thread hammering sys.monitoring.set_events (1.2M), a thread calling _testinternalcapi.invalidate_executors directly (1.5M), coverage's real global PY_START plus local LINE pattern (198k), and a generated 1200 test pytest suite doing the same mock heavy work, which passes in 4 seconds.

That last one is the interesting one. Same test count as the real suite, same kind of work, and it finishes 15 times faster and never fails. Whatever matters seems to be how much work each individual test does, not how many tests there are. The real suite spins up mock AWS servers, drives asyncio, and has deep call chains.

The real reproducer runs in about 60 seconds, so we are very happy to build a patched interpreter or run any diagnostic you want against it.

Metadata

Metadata

Assignees

No one assigned

    Labels

    interpreter-core(Objects, Python, Grammar, and Parser dirs)topic-JITtype-bugAn unexpected behavior, bug, or error

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions