[DO-NOT-MERGE] Diagnostic: JS-progress watchdog for UnitTests hangs

[bghgary]

Status: DO-NOT-MERGE — diagnostic only

[Created by Copilot on behalf of @bghgary]

Verdict

Heartbeat-fed watchdog confirms: slow progress on Ubuntu llvmpipe JSC, not a deadlock.

Run 25026066984: 27✅ 1❌. The lone ❌ is Ubuntu_GCC_JSC failing at Playground rendering with a pixel-diff (First pixel off at 108872 ... Pixel difference: 17308 pixels) — a pre-existing render flake, aborted the job before UnitTests ran. Unrelated to the watchdog.

Ubuntu_Clang_JSC (the previously-failing job) passed JavaScript.All in 141.5 s with 3 PASSED, 4 SKIPPED (ExternalTexture). No watchdog abort. WSL local run: 209 s with [watchdog-heartbeat] pump_frames=... lines visible between mocha output gaps.

Why the previous "60 → 600 s default" wasn't enough

The earlier run on this branch hit a 600-s console-output gap in Materials/Empty-ShaderMaterial and dumped a core. Post-mortem showed gtest in wait_for(16ms), all bgfx threads idle, JS thread blocked in IncrementPendingFrameScopes, DeviceImpl{m_frameBlocked=true, m_pendingFrameScopes=0, m_rendering=false, m_firstFrameStarted=true} — the same quiescent inter-frame snapshot you'd see in either slow-progress or deadlock.

A single core dump can't distinguish the two: the gtest pump loop spends almost all its wall time in wait_for(16ms), so any random-time capture lands there in either case. We needed a tiebreaker — does the render thread actually keep ticking?

Mechanism (this PR)

Two-source watchdog:

1. Console output activity (mocha lines on stdout). Existing channel.
2. Render-thread frame progress. g_pumpFrameCount (atomic), incremented after each Start/Finish cycle in the gtest pump loop.

Watchdog thread polls the atomic every 1 s. When it advances, the "last activity" timestamp resets — so a slow-but-progressing test never trips. Every 30 s, the watchdog emits [watchdog-heartbeat] pump_frames=N so we can see progress in the log even during shader-compile silence. If both sources stall for the timeout window, abort with a message that names both.

This means a real deadlock — render thread stuck in bgfx::frame() or FinishRenderingCurrentFrame() — would now trip cleanly, and slow Materials shader compiles do not.

Default restored to 60 s since false positives are eliminated.

Where it changes

• Apps/UnitTests/Source/Tests.JavaScript.cpp — atomic + watchdog dual-source logic + pump-loop increment.

Follow-ups (other PRs / repos, not this one)

• Slow llvmpipe shader compile chains in Babylon Materials/* are real and consume ~20–30% of the JSC job budget. See [DO-NOT-MERGE] Partner integration test: #1652 + #1646 #1674 for partner-side discussion. Possible mitigations: skip slowest cases on llvmpipe, bump JSC job timeout, or investigate bgfx-side llvmpipe compile cost.

[bghgary]

Update: CI completion root cause proven

Recommendation: bump Linux job timeout 30→60 min (pushed in 89a04b41). Restored full CI matrix in ee1a6662; validation run in flight.

Data

Per-phase pump-loop instrumentation pushed earlier in this branch produced the following on a slow ubuntu-latest runner (cancelled at ~16 min into UnitTests):

[watchdog-heartbeat] pump_frames=+1859 / 30 s   (≈ max framerate at 16 ms cadence)
[watchdog-heartbeat] start_ms   =+16   / 30000  (0.05 % of wall time)
[watchdog-heartbeat] finish_ms  =+36   / 30000  (0.12 % of wall time)
[watchdog-heartbeat] wait_ms    =+29943 / 30000 (99.8 % of wall time)

Per-test result on the same slow runner:

[log]   Materials
[log]     ✅ Empty ShaderMaterial should compile (620201ms)

That same test ran in 4,658 ms on a fast runner the day before — a 133× variance for the same test, same code, same workflow, different ubuntu-latest VM instance.

What this proves

• The native render thread is essentially idle during slow runs. bgfx, llvmpipe, and the GL driver are not the bottleneck (start+finish < 0.2 % of wall time).
• The bottleneck is on the JS thread — Babylon.js's scene.executeWhenReady polling, gated by JSC executing JS code.
• Cause is almost certainly noisy-neighbor on cheap GitHub-hosted VMs (JSC JIT/GC under contention). Not deadlock, not threading, not bgfx, not llvmpipe shader compile, not our code.
• Earlier "watchdog firings" on the 60s and 600s defaults were the watchdog correctly catching slow runs that would otherwise have hit the 30-min job timeout. The current heartbeat-fed watchdog (frame-counter tiebreaker) does not fire on slow-but-progressing runs — verified this session: 16 min of slow progress, no false-positive abort.

Fix in this PR

1. build-linux.yml timeout-minutes: 30 → 60. Slow runners need more headroom; 60 min covers worst observed.
2. Heartbeat-fed watchdog kept as the real-hang safety net (60 s default, frame-counter tiebreaker, opt-out via BN_WATCHDOG_TIMEOUT_S=0).
3. Per-phase pump instrumentation kept as a permanent diagnostic — it's how we'll diagnose the next CI regression in seconds instead of days.

Pixel-diff failures

Out of scope for this PR — separate issue, deferred per @bghgary.

[Responded by Copilot on behalf of @bghgary]

[bghgary]

[Responded by Copilot on behalf of @bghgary]

Correction — earlier root-cause comment was wrong.

The DRI3 / LIBGL_ALWAYS_SOFTWARE hypothesis didn't pan out. After comparing master vs rework-thread-model directly, the regression is branch-specific to anything carrying #1652, not a runner-pool issue:

• Master Linux JSC over the last 12 days: 280–470 s, 0 timeouts across 40 jobs.
• rework-thread-model (bare, no Add synchronous ExternalTexture.CreateForJavaScript and deprecate AddToContextAsync #1646, no watchdog): 5–30+ min, hits 30/60-min timeouts on contended runners.

Actual root cause

SafeTimespanGuarantor (per-named-update independent gates) was replaced in #1652 with a single shared mutex+CV+counter FrameCompletionScope gate. JS-thread SubmitCommands and similar must acquire a scope, which blocks on m_frameSyncCV while m_frameBlocked == true.

The unit-test pump was changed to:

while (!ready) {
    Start;        // open gate, notify_all
    Finish;       // wait scopes==0, close gate, bgfx::frame()
    wait_for(16ms);
}

The window between Start and Finish is ~zero. JS thread woken by notify_all has to win a scheduler race against the pump thread re-acquiring the mutex inside Finish to land its scope before the gate closes. On contended runners JS loses that race repeatedly → 16 ms + bgfx::frame() per missed scope → tests that should run 4 s take 30+ min.

Fix

Invert the pump so the gate stays open during wait_for:

Start;
while (true) {
    wait_for(16ms);   // gate OPEN here, JS thread can submit freely
    if (ready) break;
    Finish;
    Start;
}

Validation

Applied the fix on bghgary/unittest-watchdog (commit 140894be). 4 parallel runs × 2 jobs each = 8 jobs:

Run	Job	Total	Unit Tests step
25085490269	gcc	359 s	4 s
25085490269	clang	393 s	4 s
25085504626	gcc	355 s	4 s
25085504626	clang	384 s	4 s
25085506892	gcc	364 s	4 s
25085506892	clang	352 s	4 s
25085508987	gcc	362 s	4 s
25085508987	clang	377 s	4 s

All 4-second Unit Tests, total 352–393 s — back in master baseline range. Variance gone.

Open question

Should the fix live in the test pump only (committed), or also propose a change to the FrameCompletionScope gate model in #1652? Real-world consumers (Playground apps) drive Start/Finish from OS event loops with natural delays, so they likely don't hit this race the way the test pump does. Test-only is small and provably fixes CI; gate-model change is the more architectural fix but is in scope of #1652 itself. Will discuss with @bghgary on his return.

Reverted the unrelated LIBGL_ALWAYS_SOFTWARE env-var fix (it was a no-op for this).