Capture thread stacks when the nightly's Bloom hangs (BL-16612) - #8114
Merged
Conversation
The nightly visual-regression suite hangs intermittently: Bloom stops making progress, stops writing to its log, and all 12 cases then time out. Two of the four scheduled nightlies have failed this way. Every such run tells us only that something stopped — never what — because the one thing that would identify it is what each thread was doing while stuck, and we have never captured that. We cannot collect it after the fact: the suite's afterAll kills Bloom with `taskkill /T /F` before any later workflow step could look at the process. So this adds a watchdog that runs ALONGSIDE the tests, notices a Bloom.exe that has been alive far longer than a healthy run needs (~5 min healthy vs 20+ hung), and captures `dotnet-stack report` for it while it is still wedged. On the observed failures Bloom stayed stuck about 24 minutes, so there is a wide window. It takes up to 3 captures a few minutes apart: identical stacks minutes apart prove it is genuinely stuck rather than crawling. Deliberately dotnet-stack (text call stacks) and NOT dotnet-dump: this repo is public and workflow artifacts are widely downloadable, so we must not publish a memory dump of a process that holds CI secrets. Text stacks carry no heap contents. Also collects and uploads the diagnostics on SUCCESS, not just failure. Chasing an intermittent fault means the healthy runs are evidence too: without a known-good log and sample to compare against, a failing run's numbers mean little on their own. This is CI-only and purely observational — no product code, and the watchdog never signals or kills anything — so it cannot change the behavior of the run it is watching, or of Bloom for users. It is deliberately separate from, and lands ahead of, the actual fix for this hang: the fix suppresses the failure, so landing it first risks the hang never recurring and the root cause staying unknown. Verified locally: the script parses, the detached launch writes where expected, and `dotnet-stack report` against a live .NET process returns real per-thread managed stacks (exit 0, text only). Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
andrew-polk
marked this pull request as ready for review
July 27, 2026 23:18
andrew-polk
added a commit
that referenced
this pull request
Jul 27, 2026
The first green nightly on this branch was uninformative, and that is a flaw in the instrumentation rather than good news. None of the diagnostics fired at all: the page-checks navigation succeeded first try, so the retry never ran, the backstop never ran, and no worker-pool snapshot was logged. With 2 of the 4 scheduled nightlies having failed this way, a single pass would happen about half the time even with no fix, so it was worth roughly 2:1 as evidence — and it said nothing about the starvation hypothesis. The underlying problem: every diagnostic added so far speaks only AFTER something has gone wrong. If the free-worker guard is quietly doing its job, that looks exactly like a bug that quietly went away, so the root cause could stay unproven forever. So RegisterThreadBlockingAndEnsureAFreeWorker now logs when it actually has to add a worker, with the pool snapshot. That is POSITIVE evidence: if it appears in a passing run's log, the starvation condition was real and this is what kept requests moving. Logged outside the queue lock so we never hold it while writing a file. This commit originally also made the nightly collect and upload Bloom's log on success rather than only on failure, which is what let any of this be read on a green run. That half has since landed on master separately (#8114, together with the hung-Bloom stack-capture watchdog), so the rebase drops it from here. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
andrew-polk
added a commit
that referenced
this pull request
Aug 3, 2026
CI-only instrumentation so the next nightly hang tells us its cause. No product code: one PowerShell script under build/ci, purely observational, which cannot change Bloom's behavior for users or the run it watches. The watchdog from #8114 proved the hang is a hard deadlock in OffScreenBrowser.RunAndBlock -- idle, 0.72s of CPU across 24 minutes -- but its captures come from 8 minutes in, and by then they cannot answer the question that matters. The wedged thread holds the API lock, so every later request piles up behind it: a fully-consumed worker pool is the INEVITABLE consequence of any such hang, whatever made the navigation fail. So "all six workers were unavailable" at the wedge is explained by the hang rather than evidence about its cause, and cannot separate worker starvation from a WebView2 stall. The moment that does separate them is when the navigation gives up, about 26 seconds after Bloom launches. If the workers are all occupied right then, starvation caused it; if they are parked idle in WaitHandle.WaitAny, it did not, and the pool filling up afterwards is merely aftermath. So the watchdog now also captures on a trigger: it watches Bloom's log and captures the instant "Failed to navigate fully to RemoveUnwantedContentInternal" appears, then again a few seconds later, since identical stacks prove it is stuck rather than crawling. Polling drops to 5s while Bloom is young so the window is not missed, and the log's size is recorded as it grows -- which both confirms the log is readable and marks when Bloom went quiet. Deliberately NOT sampling stacks continuously: dotnet-stack starts an EventPipe session and walks every thread, so doing that every few seconds through startup could itself cause the 10-second navigation timeout we are trying to explain, manufacturing the failure under investigation. The only frequent sampling is Get-Process, a counter read. And still dotnet-stack rather than dotnet-dump: this repo is public and artifacts are widely downloadable, so we must not publish a memory dump of a process holding CI secrets. Several details exist because testing or review found them the hard way: - The trigger is edge-sensitive. It baselines the log's length when the watch starts and only searches text appended after that, because the pre-fix code logs that same line and carries on -- so a stale line from an earlier launch would otherwise keep the condition permanently true and spend both captures on the wrong moment. It rebaselines if the file shrinks (Bloom recreating it). - Read-LogText returns $null, not "", when the log cannot be read, so a momentary read failure is not mistaken for an empty/recreated log. Conflating them collapsed that baseline. - The pattern includes the DOM name: "Failed to navigate fully" is also logged by ReportInvalidFontsAsync (PublishHelper.cs:2106), a different code path. - Both captures are gated on the LATCHED fact that the alert fired, not on the line still being visible each poll, so a log hiccup cannot cancel the confirming second snapshot. - The loop stays brisk while a capture is owed; otherwise the interval reset each poll put the pair ~35s apart instead of the configured 15. - Brisk polling applies only before Bloom first appears, so a normal run does not bury the samples under hundreds of "no Bloom process running" lines. - Counters are named $triggerShotsTaken/$hungShotsTaken because PowerShell variable names are case-insensitive: $triggerCaptures WAS the parameter $TriggerCaptures, so initialising it to 0 made the capture condition 0 -lt 0 and the watchdog would have silently produced nothing. Verified by driving the script against a real .NET process: the trigger fires from a log append and yields two captures of genuine per-thread stacks; a log pre-seeded with the alert yields none; a fonts-path line yields none; a log recreated after the first capture still yields the second; and with a production-like -PollSeconds 30 the pair lands 6.7s apart. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
2 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
CI-only instrumentation so that the next time the nightly's visual-regression suite hangs, we learn why. No product code — nothing here can change Bloom's behavior for users, or the behavior of the run it is watching.
The problem it solves
The suite hangs intermittently (BL-16612) — 2 of the 4 scheduled nightlies so far. Bloom stops making progress, stops writing to its log, and all 12 cases then time out at 120s each. Every one of those runs has told us only that something stopped, never what.
What would identify it is each thread's stack while it was stuck. We cannot get that after the fact: the suite's own
afterAllkills Bloom withtaskkill /T /Fbefore any later workflow step could look at the process.What this adds
A watchdog that runs alongside the tests (
build/ci/watch-for-hung-bloom.ps1), started just before the visual-regression step. It polls for aBloom.exethat has been alive far longer than a healthy run needs — ~5 minutes healthy versus 20+ when hung — and capturesdotnet-stack reportfor it while it is still wedged. On the observed failures Bloom sat stuck for about 24 minutes, so there is a wide window to catch it.It takes up to 3 captures a few minutes apart, plus a 30-second process sample line (CPU, thread count, working set). Both matter:
dotnet-stack, deliberately notdotnet-dump. This repo is public and workflow artifacts are widely downloadable, so we must not publish a memory dump of a process that holds CI secrets.dotnet-stackemits text call stacks only — no heap contents.Diagnostics are now collected and uploaded on success too, not only on failure. Chasing an intermittent fault means the healthy runs are evidence as well: without a known-good log and sample to compare against, a failing run's numbers mean little on their own. Discarding everything from the green runs is a large part of why this has been so hard to pin down.
Safety
.gitignorelines for the scratch folders those steps create.exit 0. If the watchdog does not start, the step says so loudly in the log rather than being discovered as an empty artifact the next day.Why this lands ahead of the actual fix
There is a fix for this hang on a separate branch (#8110). It is deliberately not in this PR. The fix suppresses the failure — so if it lands first, the hang may simply stop happening and the root cause stays unknown, leaving mitigation in place justified by a hypothesis we could never test. The diagnostic opportunity is perishable; the fix can wait a few days.
Verified locally
Start-Processlaunch writes where expected — worth checking, becauseStart-Processresolves relative paths against the process working directory rather than PowerShell's location, so a wrong path would mean a watchdog that silently never starts.dotnet-stack reportagainst a live .NET process returns real per-thread managed stacks (exit 0, 4.7 KB of text, no memory contents).Ref: https://issues.bloomlibrary.org/youtrack/issue/BL-16612
Devin review
This change is