Repository navigation
Python runtime: stop a backend's log from deadlocking 2 threads - #24393
Conversation
shoumikhin
added
the
release notes: api
🔗 Helpful Links🧪 See artifacts and rendered test results at hud.pytorch.org/pr/pytorch/executorch/24393
Note: Links to docs will display an error until the docs builds have been completed. ❌ 1 New Failure, 2 Cancelled Jobs, 1 Unrelated FailureAs of commit 7a5fb48 with merge base 0f8e096 ( NEW FAILURE - The following job has failed:
CANCELLED JOBS - The following jobs were cancelled. Please retry:
FLAKY - The following job failed but was likely due to flakiness present on trunk:
This comment was automatically generated by Dr. CI and updates every 15 minutes. |
meta-cla
Bot
added
the
CLA Signed
|
@claude /pr-review |
|
Claude finished @shoumikhin's task in 20m 51s —— View job PR Review: #24393Needs Discussion: this removes the two-thread deadlock, but the new fd-2 sink can still hang a Jupyter kernel on Linux or macOS when one call logs more than the pipe holds, and it loses Python-side log capture in more places than the README says; writing the calling thread's lines out after the call returns would fix both. Detailed reviewSummaryThe PR writes runtime logs to the process's stderr with C stdio instead of
Thread Safety
Backward Compatibility
API Design
Testing
RecommendationNeeds Discussion The fd-2 sink fixes the two-thread deadlock, but it leaves a hang in a single call in Linux and macOS notebooks. It also loses Python-side capture in more places than documented. Writing the calling thread's lines from the outermost
Not done: I did not build or run anything. The ipykernel fd-capture behavior comes from its implementation and was not reproduced here. |
shoumikhin
changed the title
|
Thanks, the latest push does this. Fatal lines and lines logged outside a call still go straight to the process's stderr. The stderr redirect tests are back to their original form, and the docs page and the deadlock test are updated as suggested. |
shoumikhin
changed the title
|
@claude /pr-review |
|
Claude finished @shoumikhin's task in 31m 19s —— View job PR Review: #24393Request Changes: buffering a call's log lines fixes the deadlock, but a call that crashes or hangs now loses its logs even in a plain terminal, where nothing needs the buffering; buffering only when Detailed reviewSummaryThe PR keeps the runtime log lines of each binding call and writes them to One major problem: a call that crashes or hangs loses its lines, even when nothing captures
Code Quality
Testing
API Design
Thread Safety
Backward Compatibility
RecommendationRequest Changes Losing the logs of a call that crashes or hangs in a plain terminal is avoidable: buffer only when
Not done: I did not build or run anything. pybind11 is not checked out here, so the pybind11, CPython and glibc behavior cited above comes from their sources, not from a run. |
shoumikhin
changed the title
shoumikhin
changed the title
4ca018c to
7ecff8d
Compare
|
Thanks, reworked along those lines. While A write that fails or is cut short now always falls back to the process's stderr, even if that repeats some lines, and a Ctrl-C raised in it is raised again once the call returns. The saved exception and its allocation are gone. A fatal line is now just that line, written at once while stderr has room. The README states what a long call keeps. Tests cover the direct writes, a full pipe, the cap with its note and escaping, a failed or interrupted write, and the fatal line, which a too-small ETDump debug buffer triggers. The daemon thread crash at exit is real. On Linux, Python 3.13 and earlier end a daemon thread at exit with |
|
@claude /pr-review |
|
Claude finished @shoumikhin's task in 46m 51s —— View job Request Changes: the daemon-thread rule applies on platforms and Python versions where the crash it guards against cannot happen, a fatal line leaves behind the kept lines that explain it, and the new UTF-8 escaping leaves the main error message raw; each needs a small change. Detailed reviewPR Review: #24393SummaryThe PR stops the pybindings log callback from calling Python. A backend that logs while holding its own lock can no longer deadlock with a thread that waits for that lock. Lines now go to fd 2 through C stdio, or wait until the outermost binding call returns. Three problems below need small changes before merge; five more are minor. Code Quality
API Design
Backward Compatibility
RecommendationRequest Changes. Three fixes are needed before merge, and each is a few lines: limit the daemon-thread rule to Linux with Python < 3.14, write the kept lines before a fatal line, and escape the whole exception message. The other five items can land in a follow-up.
Not done: I did not build or run anything. pybind11 is not checked out here, so the pybind11, CPython and ipykernel behavior cited above comes from their sources and docs rather than this checkout. |
|
Claude finished @shoumikhin's task in 58m 35s —— View job Approve. Nothing here blocks the merge; all the remaining issues are minor:
Detailed reviewPR Review: #24393SummaryThe PR writes runtime logs to fd 2 through C stdio, so a backend that logs while holding its own lock can no longer deadlock with a thread waiting for the GIL. When Code Quality
Testing
API Design
Performance
RecommendationApprove All seven findings are minor. The fixes worth making first are the fatal path and the per-line polling; the rest are small edits.
Not done: I built and ran nothing. |
bd9384d to
b1424ae
Compare
|
Changed in this push: a fix for a hang at exit, a test fix for Windows, and the README and comment fixes from the review. With That write now goes out only while fd 2 has room and drops the rest, as a daemon thread already does when On Windows the LLM runner is not built, and its package then raises RuntimeError rather than ImportError. The test for lines logged outside a call caught only ImportError, so it failed there instead of skipping. The pybindings tests that import the LLM runner now catch both. |
|
Thanks. Fatal line and the lines waiting for the main thread. Right, a fatal line writes only the lines its own call kept. As you note, main loses those lines too, so this is not a regression. I kept the fatal path minimal, and the README now says that this abort loses the lines still waiting. Import under a redirect. Right. Until the first binding call, such a line then waits for the main thread instead of going out at once. It still reaches stderr unless the process aborts first. Caching
Exit path tests. Added in this push: the daemon-thread test registers an exit hook that runs after the bindings' own, checks that lines logged then reach fd 2, and that a full pipe no longer hangs the exit. Only the hook's flush of lines already waiting stays untested: Python still wrote them without the hook, so no test fails without it. README exit sentence. Fixed in this push: it now covers only the lines waiting for the main thread. Polling outside a call, and order. Right on both. It needs a pipe that stays full and a thread that logs outside a call with the GIL held, so I left it for the follow-up that writes waiting lines from their own thread. Socket on fd 2. Right. A socket gets no room check, and unlike main, a write to a full one blocks with the GIL held. Treating a socket like a pipe fits the same follow-up. |
|
@claude /pr-review |
|
Claude Code is working… I'll analyze this and get back to you. |
|
@claude /pr-review |
|
Claude finished @shoumikhin's task in 54m 52s —— View job Approve: nothing blocks merging. The main issue is that lines waiting for Python's main thread are written by a pending call, which can re-enter a replaced Detailed reviewPR Review: #24393SummaryThe PR stops the PAL log hook from calling Python, so a backend that logs while it holds its own lock no longer deadlocks another thread. Each line now goes to fd 2 through C stdio, waits for its binding call to return, or waits for Python's main thread through
Thread Safety
Infrastructure
Code Quality
RecommendationApprove. Nothing here blocks merging. The re-entry and ordering of lines that wait is the finding most worth fixing. The others are one README sentence, one Buck dep and a cleanup. Not done
|
|
Thanks. Answers, without code changes: Re-entry and order. Right, the main thread's pending call runs between bytecodes, so it can run inside a Threads that do not hold the GIL. Right, and as you note, the main branch blocks the same way. The follow-up will also hand such a line to its writer thread when fd 2 has no room, so I did not add it to the README as a new limit. Buck. Right, these tests skip under Buck. The CMake jobs run them on Linux and macOS. No Buck job in this repo runs these tests, so I could not try the runner dependency and left it out. Comments and helper. The helper names the rule for lines logged outside a call, which keeps the log function short, so I kept it. The follow-up rewrites this routing, and I will merge the comments there. |
The Python bindings wrote each runtime log line through sys.stderr.write as it was logged, whenever the logging thread held the GIL (Python's global interpreter lock). A backend can log while it holds its own lock, as XNNPACK does when a load fails, and a Python write can let another thread take the GIL. If that thread then waits for the backend's lock, for example to execute or to destroy a method, the first thread never gets the GIL back and both hang. The log function no longer calls Python. While sys.stderr is still the stream Python opened on the process's stderr, each line goes straight there through C stdio, so a terminal or a log file sees it at once, even if the process later crashes. When Python has replaced sys.stderr, as pytest's capsys, contextlib.redirect_stderr and Jupyter do, most lines still reach it. A binding call keeps its lines and writes them to sys.stderr as it returns, when no backend lock is held. A line that Python's main thread logs outside any binding call, for example while the LLM runner loads, is written by that thread before it runs more Python code, so it still lands in a short redirect. It logged the line from native code, so it is not inside its own sys.stderr.write. A line from any other thread goes to a thread that the bindings start for it. A binding call's lines then follow the lines its thread handed to that thread, so one thread's lines keep their order. Python's main thread may be in the middle of a sys.stderr.write whose stream holds a lock, and a write nested there would wait for that lock forever. Outside a call, only a thread that holds the GIL can tell where sys.stderr goes, by comparing it with the stream checked last, a check that runs no Python code. A thread that does not hold the GIL writes to the process's stderr, as before, so a notebook with ipykernel's fd capture off does not show its lines. Lines from a thread that holds the GIL do reach such a notebook. On Linux and macOS, a line also waits once the process's stderr is a pipe or socket that stays full for 100 ms, so a thread that holds the GIL does not hang on it while a Python thread in the same process drains it. The rest of a binding call's lines then wait for the call to return. A line logged outside a call does not wait: the bindings' thread writes it without the GIL or any lock that Python's exit needs. While that thread writes, a binding call's lines wait for the call to return, since it can take the room a check just saw. A terminal is written at once, since its reader is another process. The process can still hang if another writer fills the pipe right after the check for room, or if a Python thread in the same process reads a terminal that is its stderr. macOS reports room in a small pipe that it may not have, so there a pipe that has not grown past 16 KiB takes a line only once it fits in 512 bytes beside what the pipe holds. Up to 1 MiB of lines wait at a time, keeping the newest and noting how much was left out. A fatal line goes out at once while there is room, with the lines its call kept, since an abort usually follows. If writing to sys.stderr fails, the lines go to the process's stderr instead, and a Ctrl-C raised in that write is raised again once the call returns. Once Python starts to exit, the lines still waiting are written, and later lines logged outside a call go to the process's stderr while it has room. Lines for the process's stderr are left out instead while the bindings' thread is still writing to it. On Linux with Python before 3.13.8, a daemon thread never writes its lines through Python. Those versions can end such a thread at exit in the middle of that write, and the unwinding then releases Python objects without the GIL and crashes the process. The old log function crashed this way too. The bindings' thread writes the daemon thread's lines instead. New tests cover the hang, also when the LLM runner logs under XNNPACK's lock outside any call, a sys.stderr whose write runs Python code while it holds a lock, daemon threads that log while Python exits, lines logged outside a call with sys.stderr replaced before or after import or left alone, a daemon thread's lines with a replaced sys.stderr, a failing write, a fatal line and the line before it, a call that dies in a busy terminal, a full pipe or socket drained by a thread, for a call, for the LLM runner and for both at once, and a long call's newest lines. The docs example for registering a PAL (platform abstraction layer) now uses the right namespace and compiles on its own, and the docs say why the bindings' log function never calls Python.
…rupt program The bindings add the runtime's error lines to the exceptions they raise. Some of those lines carry raw bytes from the input, such as 4 bytes near the start of a file that is not a program, which the runtime prints as its identifier. The message itself is cut to fit 128 bytes, which can split a character of a path. Python rejects an exception message that is not valid UTF-8, so such a load raised UnicodeDecodeError instead of RuntimeError. The whole message is now decoded with backslashreplace, so those bytes show as escapes. The long-call test, which loads such a file, now expects RuntimeError, and a new test loads paths whose message is cut inside a character.
b1424ae to
7a5fb48
Compare
|
What changed since the last push:
New tests cover a stream whose |
|
@claude /pr-review |
PR Review: #24393
|
|
@JacobSzwejbka, on the notebook question: I reran the logging cases on this head in a real Jupyter kernel (ipykernel 7.4, Python 3.12) with fd capture off, next to main.
With fd capture on, every case matches main, including the fatal case, where the lines are lost with both builds. |
|
@claude /pr-review |
PR review in progress
|
|
@claude review this PR |
|
Claude finished @shoumikhin's task in 8m 33s —— View job Approve: nothing blocks merging. The main problems are in how Python's main thread re-queues and orders the lines it hands off, plus a possible use-after-free at exit (low confidence); the rest are a README contradiction and one minor write-path issue. Detailed reviewPR Review: #24393SummaryThe PR keeps the PAL log hook from calling Python. Each line goes to fd 2, waits for its binding call to return, or waits for Python's main thread ( Thread Safety
API Design
Code Quality
RecommendationApprove. Nothing here blocks merging. The re-queue loop and the main-thread ordering are the fixes most worth making, and each is a few lines in
Not done: nothing was built or run, and Python was not available to this job. The exit-time crash and the CPython eval-breaker behavior come from reading code. |
|
@pytorchbot cherry-pick --onto release/1.6 -c critical |
Cherry picking #24393The cherry pick PR is at #24529 and it is recommended to link a critical cherry pick PR with an issue. Details for Dev Infra teamRaised by workflow job |
What is wrong today
2 threads can hang forever when a backend logs while holding a lock, as XNNPACK does when a load fails. A log line from a thread that holds the GIL (Python's global interpreter lock) goes to
sys.stderrat once, and that Python write can let another thread take the GIL. If that thread then waits for the lock, neither thread moves again:What this change does
The log function never runs Python code. While
sys.stderris the process's stderr (fd 2), each line goes straight to fd 2.When Python has replaced
sys.stderr(capsys,redirect_stderr, a Jupyter notebook), the lines wait:redirect_stderrblock.sys.stderr.write, so a stream whosewritetakes a lock cannot hang.Outside a binding call, threads that do not hold the GIL write to fd 2, as today. Up to 1 MiB waits, keeping the newest.
On Linux and macOS, a line also waits while fd 2 is a pipe or socket that stays full, so a GIL holder does not block while a Python thread drains it (
wurlitzer.pipes()). A terminal is written at once, since its reader is normally another process. A fatal line goes to fd 2 at once while there is room.On Linux with Python before 3.13.8, a daemon thread never writes through Python. Today it does, and Python can end it mid-write at exit, which crashes the process.
Tests
New tests cover the hang (also from the LLM runner), a stream whose
writetakes a lock, a full pipe or socket drained by a thread, lines inside a short redirect, daemon threads at exit, and cut error messages. Ran them on Linux x86_64 and macOS, and the logging cases in Jupyter with fd capture on and off.Also fixed: an error message with invalid UTF-8, such as a corrupt program's identifier, raised
UnicodeDecodeError, notRuntimeError. The docs on registering a PAL (platform abstraction layer) now use the right namespace and a complete example.