Skip to content

Commit 9fd48c8

Browse files
authored
🐛 fix(ci): dump stacks from a thread that holds the GIL (#3377)
1 parent 5183a10 commit 9fd48c8

2 files changed

Lines changed: 67 additions & 28 deletions

File tree

‎tasks/pytest_diagnostics.py‎

Lines changed: 30 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,7 @@
66
import faulthandler
77
import os
88
import sys
9+
import threading
910
from datetime import datetime, timezone
1011
from pathlib import Path
1112
from typing import TYPE_CHECKING, Final
@@ -18,6 +19,9 @@
1819

1920
# faulthandler has one timer per process, including nested pytest sessions.
2021
_DIAGNOSTICS: Final[list[_Diagnostics]] = []
22+
# faulthandler's native timer walks other threads' frames without the GIL and can crash or hang CPython, so it only
23+
# backs up the dump thread: re-armed after every dump, it fires once a thread holds the GIL long enough to stall it
24+
_STALL_INTERVALS: Final[int] = 10
2125

2226

2327
def pytest_addoption(parser: pytest.Parser) -> None:
@@ -50,40 +54,54 @@ def __init__(self, directory: Path, interval: float) -> None:
5054
"w", encoding="utf-8", buffering=1
5155
)
5256
self.interval: Final[float] = interval
57+
# pytest also arms and cancels the native timer, and free-threaded builds race concurrent faulthandler calls
58+
self._faulthandler_lock: Final[threading.Lock] = threading.Lock()
59+
self._stopped: Final[threading.Event] = threading.Event()
5360
self._record(f"START pid={os.getpid()} parent={os.getppid()} python={sys.version}")
54-
self._arm_timer()
61+
self._arm_stall_timer()
62+
self._dumper: Final[threading.Thread] = threading.Thread(
63+
target=self._dump_periodically, name="pytest-diagnostics", daemon=True
64+
)
65+
self._dumper.start()
5566
atexit.register(self._close)
5667

5768
def _record(self, message: str) -> None:
5869
self.stream.write(f"{datetime.now(timezone.utc).isoformat()} {message}\n")
5970

60-
def _arm_timer(self) -> None:
61-
faulthandler.dump_traceback_later(self.interval, repeat=True, file=self.stream)
71+
def _arm_stall_timer(self) -> None:
72+
with self._faulthandler_lock:
73+
faulthandler.dump_traceback_later(self.interval * _STALL_INTERVALS, repeat=True, file=self.stream)
74+
75+
def _dump_periodically(self) -> None:
76+
while not self._stopped.wait(self.interval):
77+
self._record("DUMP")
78+
# holds the GIL, or stops the world on free-threaded builds, so no frame is freed while it reads
79+
faulthandler.dump_traceback(file=self.stream)
80+
self._arm_stall_timer()
6281

6382
def retain_crash_traceback(self) -> None:
6483
# pytest's captured stderr can disappear with a crashed xdist worker.
65-
faulthandler.enable(file=self.stream)
84+
with self._faulthandler_lock:
85+
faulthandler.enable(file=self.stream)
6686

6787
def pytest_runtest_logstart(self, nodeid: str) -> None:
6888
self._record(f"TEST {nodeid}")
6989

7090
def pytest_runtest_logreport(self, report: pytest.TestReport) -> None:
7191
self._record(f"{report.when} {report.outcome} {report.nodeid}")
7292

73-
@pytest.hookimpl(trylast=True)
74-
def pytest_exception_interact(self) -> None:
75-
# pytest's faulthandler plugin cancels the timer when reporting an exception.
76-
self._arm_timer()
77-
7893
@pytest.hookimpl(trylast=True)
7994
def pytest_unconfigure(self) -> None:
8095
self.retain_crash_traceback()
8196
self._record("STOP")
8297

8398
def _close(self) -> None:
84-
# Keep the watchdog alive during xdist worker shutdown, after pytest has returned.
85-
faulthandler.cancel_dump_traceback_later()
86-
faulthandler.disable()
99+
# Keep dumping through interpreter shutdown, after pytest has returned.
100+
self._stopped.set()
101+
self._dumper.join()
102+
with self._faulthandler_lock:
103+
faulthandler.cancel_dump_traceback_later()
104+
faulthandler.disable()
87105
self._record("EXIT")
88106
self.stream.close()
89107

‎tests/tasks/test_pytest_diagnostics.py‎

Lines changed: 37 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -20,7 +20,11 @@ def wait_for_stack(function: str) -> None:
2020
while time.monotonic() < deadline:
2121
text = path.read_text(encoding="utf-8")
2222
controller = next(Path("diagnostics").glob("controller-*.log")).read_text(encoding="utf-8")
23-
if text.count("Timeout (") >= 2 and f"in {function}\\n" in text and "pytest_runtestloop" in controller:
23+
if (
24+
text.count(" DUMP\\n") >= 2
25+
and f"in {function}\\n" in text
26+
and all("pytest_runtestloop" in log for log in (text, controller))
27+
):
2428
return
2529
time.sleep(0.01)
2630
raise TimeoutError("stack dumps did not capture the blocked pytest process")
@@ -48,7 +52,7 @@ def test_diagnostics_capture_controller_and_workers(diagnostic_pytester: pytest.
4852
}
4953
assert set(logs) == {"controller", "gw0", "gw1"}
5054
for worker, text in logs.items():
51-
assert text.count("Timeout (") >= 2
55+
assert text.count(" DUMP\n") >= 2
5256
assert "pytest_runtestloop" in text
5357
assert "pid=" in text
5458
assert "parent=" in text
@@ -76,7 +80,7 @@ def test_wait_for_stack() -> None:
7680
text: Final[str] = next((diagnostic_pytester.path / "diagnostics").glob("*.log")).read_text(encoding="utf-8")
7781
assert "call failed" in text
7882
assert "in test_wait_for_stack\n" in text
79-
assert "Timeout (" in text
83+
assert " DUMP\n" in text
8084

8185

8286
def test_diagnostics_survive_abrupt_exit(diagnostic_pytester: pytest.Pytester) -> None:
@@ -91,7 +95,7 @@ def test_wait_for_stack() -> None:
9195
assert diagnostic_pytester.runpytest_subprocess(timeout=30).ret == 23
9296
text: Final[str] = next((diagnostic_pytester.path / "diagnostics").glob("*.log")).read_text(encoding="utf-8")
9397
assert "in test_wait_for_stack\n" in text
94-
assert "Timeout (" in text
98+
assert " DUMP\n" in text
9599
assert "STOP" not in text
96100

97101

@@ -135,10 +139,31 @@ def test_wait_after_nested_pytest() -> None:
135139
assert "in test_wait_after_nested_pytest\n" in text
136140

137141

142+
def test_diagnostics_dump_when_gil_held(diagnostic_pytester: pytest.Pytester) -> None:
143+
# a backtracking regex keeps the GIL for over a second, longer than the stall timer's 10 intervals
144+
diagnostic_pytester.makepyfile(
145+
"""
146+
import re
147+
import time
148+
from pathlib import Path
149+
150+
def test_hold_the_gil() -> None:
151+
log = next(Path("diagnostics").glob("controller-*.log"))
152+
deadline = time.monotonic() + 20
153+
while "Timeout (" not in log.read_text(encoding="utf-8"):
154+
assert time.monotonic() < deadline, "the stall timer never fired"
155+
re.fullmatch(r"(a+)+b", "a" * 26)
156+
"""
157+
)
158+
diagnostic_pytester.runpytest_subprocess(timeout=30).assert_outcomes(passed=1)
159+
text: Final[str] = next((diagnostic_pytester.path / "diagnostics").glob("*.log")).read_text(encoding="utf-8")
160+
_, header, after = text.partition("Timeout (")
161+
assert (header, "in test_hold_the_gil\n" in after.split(" DUMP\n", 1)[0]) == ("Timeout (", True)
162+
163+
138164
def test_diagnostics_capture_shutdown_wait(diagnostic_pytester: pytest.Pytester) -> None:
139165
diagnostic_pytester.makeconftest(
140166
"""
141-
import faulthandler
142167
import os
143168
import threading
144169
import time
@@ -150,17 +175,13 @@ def pytest_unconfigure() -> None:
150175
151176
def wait_for_shutdown() -> None:
152177
path: Final[Path] = Path("diagnostics") / f"controller-{os.getpid()}.log"
153-
try:
154-
deadline: Final[float] = time.monotonic() + 20
155-
while time.monotonic() < deadline:
156-
tail = path.read_text(encoding="utf-8").rsplit("STOP\\n", 1)[-1]
157-
if tail.count("in _shutdown\\n") >= 2 and "in wait_for_shutdown\\n" in tail:
158-
return
159-
time.sleep(0.01)
160-
raise TimeoutError("no stack dump during shutdown")
161-
finally:
162-
# Keep this thread alive until the native watchdog finishes reading its frames.
163-
faulthandler.cancel_dump_traceback_later()
178+
deadline: Final[float] = time.monotonic() + 20
179+
while time.monotonic() < deadline:
180+
tail = path.read_text(encoding="utf-8").rsplit("STOP\\n", 1)[-1]
181+
if tail.count("in _shutdown\\n") >= 2 and "in wait_for_shutdown\\n" in tail:
182+
return
183+
time.sleep(0.01)
184+
raise TimeoutError("no stack dump during shutdown")
164185
"""
165186
)
166187
diagnostic_pytester.makepyfile("def test_empty() -> None: pass")

0 commit comments

Comments
 (0)