Skip to content

client.stall: heartbeat counts WebKit timer throttling as stalls on macOS #99

Closed

Description

@mubeda

Summary

On the macOS desktop app, the Profiler raises client.stall ("The interface stalled for …") while the user is doing nothing and the window is covered or on another Space. The client heartbeat counts WKWebView's timer throttling as main-thread stalls, and the server sums them into a finding. This is separate from the snapshot stalls under #89, which v0.9.2 fixed. The heartbeat and threshold code is unchanged since v0.9.0. Evidence first posted in #89 (comment).

Environment

Field Value
BiBCode 0.9.1 (inferred: the profiler does not record the version, see #98), desktop (DMG); the code is unchanged in 0.9.2
OS macOS 27.0.1, arm64
Mode local
Finding client.stall-93202704f780: warn, seen 40 times from 2026-10-13T12:34:41Z to 2026-10-13T14:19:27Z
Fingerprint 93202704f780
Capture native dumps available, OS crash records available

Evidence

  • 2c8b1f06-166 to 2c8b1f06-284 client.batch: 10 to 11 stalls per batch of about 550 to 600 ms each (for example 2c8b1f06-174: 11 stalls, 5,543 ms total, max 593 ms). windowMs was 11000 instead of about 10004, and flush times snapped to whole seconds: both timers were clamped to about 1 s.
  • 2c8b1f06-172, -201, -213 client.request: renderMs 276, 484 and 309 against about 20 ms normally, which fits an occluded window that is waiting on animation frames.
  • interactions.maxMs was 0 throughout. The only traffic was the 2 s server.getProcessDiagnostics poll and the 30 s provider-usage refresh. 2c8b1f06-1403, -1415 process.sample: the desktop host used 0.1 % CPU.
  • 2c8b1f06-1409 client.batch: one isolated 3,514 ms late tick (windowMs 12279) with clean batches on both sides. The data cannot tell harder throttling from a real long task.

Suspected source

  • apps/web/src/profiler/clientCollector.ts:171-181: without Long Animation Frames (WKWebView has none), any heartbeat lateness over STALL_OVER_MS (50 ms) counts as a stall.
  • apps/web/src/profiler/clientCollector.ts:95-97, :188-192: the heartbeat pauses only on visibilityState === "hidden". An occluded window, or one on another Space, stays "visible".
  • apps/server/src/diagnostics/profiler/client.rs:46, :380: STALL_FINDING_MS (1000) applies to totalMs, so about 11 throttled ticks clear it.

Reproduction

  1. Turn on the Profiler in the macOS desktop app.
  2. Cover the window fully, or move it to another Space without minimizing it, for 1 to 2 minutes.
  3. Run profiler events --kind client.batch --since 10m --json. Expect about 10 stalls of about 550 ms per batch, windowMs about 11000, and a new client.stall.
  4. Bring the window to the front. The stalls stop.

Root-cause hypothesis

WKWebView throttles DOM timers to about 1 s alignment while the window is occluded but the page is still "visible". The heartbeat reports each clamped tick as a stall. Confidence: high for the periodic occurrences, because of the uniform about 1 s cadence, the drift of the flush timer and the idle host. Low to medium for the single 3.5 s tick.

Suggested fix direction

Pause the heartbeat (bump epoch) when the desktop bridge reports the window unfocused or occluded, not only when the page is hidden. Alternatively, drop windows where the flush timer itself fired late. Consider raising the finding on maxMs over 1000 ms rather than on totalMs, so short throttled ticks cannot add up while real single long stalls still count.

Activity

  1. added
    bugSomething is broken or behaving incorrectly.
    on Oct 14, 2026
  2. mubeda commented on Oct 14, 2026

    @mubeda
    OwnerAuthor

    New occurrence of client.stall-93202704f780 (profiler fingerprint 93202704f780):

    Field Value
    BiBCode 0.9.2, desktop (DMG) (the issue reported 0.9.1)
    OS macOS 27.0.1, arm64
    Count 41 at 2026-10-14T15:54:58Z (77 by 16:24Z, see below)

    What is new: a second trigger for false stalls, which is resuming after the display was off. The heartbeat counts the first ticks after the page resumes as stalls.

    • No client.batch from 14:56:26Z to 15:54:58Z: the client was suspended while the display was off. During that gap the server's process.sample ticks were irregular (for example 18910b78-1259 to -1260, 91 s apart) and selfCpuMs showed catch-up bursts of about 1.1 s.
    • macOS pmset -g log shows "Display is turned on" at 15:54:46Z.
    • 18910b78-1278 client.batch at 15:54:58Z, the first after resume: 3 stalls, 1,487 ms total, max 1,220 ms, windowMs 10001, interactions.count 0. Every batch after it is clean (18910b78-1280 onward).
    • The same thing happened at the next display-on (16:11:48Z): 18910b78-1325, 1 stall of 300 ms.

    Suggested fix direction, in addition to the occlusion handling above: bump the heartbeat epoch, discarding stalls, when the page resumes after a long gap. Signals include visibilitychange or pageshow, a desktop-bridge wake or occlusion event, or a heartbeat tick later than a few seconds, which cannot be a real long task and should not count.

    Note for the fix: the same fingerprint also recorded real stalls from 16:12Z to 16:24Z (18910b78-1326 to -1465). The window was focused and the user was scrolling a long conversation. Flush windows stayed at about 10 s, there were 7 to 15 stalls of 200 to 930 ms per batch, Event Timing interactions reached 672 ms (client.interaction-1bb57fd93dcf), and replies with a server time of 13 ms or less waited 250 to 900 ms on the client (rpc.slow-37b7a238df64, rpc.slow-ee0e8d26aa17). Those are not throttling, and filtering must keep them. They are being investigated separately.

  3. mubeda commented on Oct 14, 2026

    @mubeda
    OwnerAuthor

    New occurrence of client.stall-93202704f780 (profiler fingerprint 93202704f780):

    Field Value
    BiBCode 0.9.2, desktop (DMG) (the issue reported 0.9.1)
    OS macOS 27.0.1, arm64
    Count 393, last seen 2026-10-14T19:13:12Z

    What is new: real stalls up to 6.2 s with the window in use, not throttling, and a sampled main-thread stack. These are tracked in a separate issue.

    • 97f7ca61-5150 client.batch: 6 stalls, 13,600 ms total, the longest 6,189 ms, windowMs 10,001, so the flush timer was on time.
    • The WebKit WebContent process was at 55 to 102 % CPU. A 5 s sample puts about 73 % of the main thread in WebCore::LabelsNodeList traversal (labels[0]), traced to Base UI's per-commit useAriaLabelledBy fallback. Details: rpc.slow: Base UI label lookup on every render saturates the macOS webview #106.

    When fixing this issue's throttling false positives, keep client.stall able to report real stalls like these.

  4. mubeda commented on Oct 15, 2026

    @mubeda
    OwnerAuthor

    Shipped in v0.9.3 (85db8d1, 5f6fb19).

    The web collector now tracks whether the window is in the background (hidden, blurred) and gives a 20 s grace after it comes back, so WebKit's timer throttling of a covered or background window, and the catch-up right after waking, no longer count as client.stall.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething is broken or behaving incorrectly.profiler:93202704f780client.stall profiler finding

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions