Audio stutter stack audit: the pacer carried its debt, the Deck callback was not realtime, and the client log ring evicted its own audio line #292

Merged

enricobuehler merged 4 commits from worktree-audio-stutter-stack-audit into main 2026-08-18 10:41:05 +00:00

Conversation 0 Commits 4 Files Changed 13

+732 -92

enricobuehler commented 2026-08-18 10:29:10 +00:00

Owner

Copy Link

Copy Source

Follow-up to the 2026-08-17 field bundle (host Skynet on canary g33538582, Steam Deck client 0.30.0): audio still stutters after 0.30.0 for this reporter, for other Deck users, and on clean links. This branch is the code half of an end-to-end audit of the audio path (host capture → host pacer → wire → every client ring). Full write-up with the findings ledger, mechanism model and the reporter asks: https://claude.ai/code/artifact/322a6d1a-b6df-42d2-a31f-c398aadcb03f

What the log proved

• The client half of the merged bundle was empty: … 2037456 older lines evicted from the ring … — the vendored H.265 parser logs ~1 250 DPB DEBUG lines a second and the 4 096-line ring turned over every three seconds. The audio playback buffer_ms= underruns= line three rounds had asked for was written every 10 s and evicted every 3 s.
• Host capture: 89–98 % delivered, 28–118 gaps per 30 s of ~30 ms, callback thread realtime (rt_priority=20) — the holes are upstream of our node. Gap counts alternate high/low on consecutive 30 s windows for 26 minutes (a ~60 s periodic stall on that box; VirtualHere's DualSense USB audio card driving the graph is the leading suspect, being tested).
• Host egress: 33–72 % of departures "late", max_late_ms to 99, reanchors≈0, max_spacing_ms=13 — a free-running send schedule that fell behind by every sub-threshold loss and only repaid the debt as a burst of ~20 silence frames.

Commits (one concern each)

1. aa070d1f feat(host,audio): capture line gap histogram — CaptureStats::observe_gap shared by the Linux cadence feed and the Windows discontinuity feed; both desktop audio capture lines gain gap_hist=a/b/c/d (<20/<50/<100/≥100 ms) and missing_ms=, so sixty 30 ms stalls and fifty-nine hiccups plus one outage stop reading the same. The Windows loopback reader thread now takes the same boost_thread_priority(true) the sender it feeds has had (it ran at normal priority beside it).
2. dc2d9469 fix(host,audio): the pacer's schedule was wall clock, the source was not — the infill decision now looks at max(since_last_chunk, schedule_lag), so uncompensated sub-threshold losses can no longer accumulate into a debt burst; InfillPolicy::after() follows the real quantum (note_quantum: one chunk + one frame, never less than two frames — bit-identical at a frame-sized quantum, and no longer mid-cycle on a VM's clamped 1024-frame buffer); a slot whose remaining backlog exceeds one chunk + one frame sends a second frame (a fast source clock could only ever grow host latency before); hole edges fade 1 ms out/in (pcm::raised_cosine_tail/head, now pub) instead of stepping to digital zero.
3. 8effeb79 fix(client,audio): the Deck playback callback ran on our own thread at nice 0 — the PipeWire playback stream connects with RT_PROCESS (the graph rendered silence for our node whenever our main-loop thread missed the 5 ms cycle — invisible to every counter); the callback is RT-safe (pre-reserved ring, no logging); new audio_vitals::PlaybackVitals atomics on both twins, and the decode thread prints the same audio playback … / audio playback quantum lines on wall clock (same field names — greps keep working, one logging site for PipeWire and WASAPI); best-effort setpriority(-10) on the decode thread.
4. f9b5673d fix(client): the vendored decoder's DPB chatter evicted the whole log ring — the session's RingLayer normalizes log-bridge events to their real target (host log_capture.rs recipe) and drops cros_codecs at DEBUG/TRACE (its WARN+ still lands, log.* bookkeeping fields dropped). Tested end to end through the bridge. Cargo.lock gains two direct deps already in the graph.

Not in this PR (documented in the report)

Symmetric depth correction in JitterPolicy (sync-driven deepening today = hollow → the next late packet de-primes a full target — all four clients), rtkit/MMCSS for the client audio threads (Windows client render thread still unboosted; its pinned windows-rs revision could not be compile-checked from the Mac), a session-scoped debounce of library fs-change reconciles (102 in 27 min), and making our PipeWire sink drive its own group so no hardware card can clock the game→punktfunk path.

Gate

• Host (punktfunk-rust-ci, amd64): cargo fmt --check · clippy --all-targets -p punktfunk-host -p punktfunk-core -- -D warnings · plain build · tests — 466 core + 603 host, 0 failed, non-vacuous.
• Client (pf-gtkflow): same for pf-client-core + punktfunk-client-session — 220 + 4 + 1, 0 failed.
• New tests: gap_histogram_gives_the_shape_and_the_cost, infill_threshold_follows_a_clamped_quantum, the_head_fade_mirrors_the_tail_fade, bridged_decoder_debug_is_dropped_and_the_audio_line_survives, counters_accumulate_and_gauges_overwrite — all confirmed present via --list.
• Apple/Android untouched. The pacer's inner loop is thread plumbing with no unit test; on-glass verification (a Deck against a lossy host) is owed and the reporter's next canary log is the first data point (gap_hist= will be on it, and the Deck bundle will finally carry its audio line).

Follow-up to the 2026-08-17 field bundle (host Skynet on canary `g33538582`, Steam Deck client 0.30.0): audio still stutters after 0.30.0 for this reporter, for other Deck users, and on clean links. This branch is the code half of an end-to-end audit of the audio path (host capture → host pacer → wire → every client ring). Full write-up with the findings ledger, mechanism model and the reporter asks: https://claude.ai/code/artifact/322a6d1a-b6df-42d2-a31f-c398aadcb03f ## What the log proved - **The client half of the merged bundle was empty**: `… 2037456 older lines evicted from the ring …` — the vendored H.265 parser logs ~1 250 DPB DEBUG lines a second and the 4 096-line ring turned over every three seconds. The `audio playback buffer_ms= underruns=` line three rounds had asked for was written every 10 s and evicted every 3 s. - **Host capture**: 89–98 % delivered, 28–118 gaps per 30 s of ~30 ms, callback thread realtime (`rt_priority=20`) — the holes are upstream of our node. Gap counts alternate high/low on consecutive 30 s windows for 26 minutes (a ~60 s periodic stall on that box; VirtualHere's DualSense USB audio card driving the graph is the leading suspect, being tested). - **Host egress**: 33–72 % of departures "late", `max_late_ms` to 99, `reanchors≈0`, `max_spacing_ms=13` — a free-running send schedule that fell behind by every sub-threshold loss and only repaid the debt as a burst of ~20 silence frames. ## Commits (one concern each) 1. **`aa070d1f` feat(host,audio): capture line gap histogram** — `CaptureStats::observe_gap` shared by the Linux cadence feed and the Windows discontinuity feed; both `desktop audio capture` lines gain `gap_hist=a/b/c/d` (<20/<50/<100/≥100 ms) and `missing_ms=`, so sixty 30 ms stalls and fifty-nine hiccups plus one outage stop reading the same. The Windows loopback **reader** thread now takes the same `boost_thread_priority(true)` the sender it feeds has had (it ran at normal priority beside it). 2. **`dc2d9469` fix(host,audio): the pacer's schedule was wall clock, the source was not** — the infill decision now looks at `max(since_last_chunk, schedule_lag)`, so uncompensated sub-threshold losses can no longer accumulate into a debt burst; `InfillPolicy::after()` follows the real quantum (`note_quantum`: one chunk + one frame, never less than two frames — bit-identical at a frame-sized quantum, and no longer mid-cycle on a VM's clamped 1024-frame buffer); a slot whose remaining backlog exceeds one chunk + one frame sends a second frame (a fast source clock could only ever grow host latency before); hole edges fade 1 ms out/in (`pcm::raised_cosine_tail/head`, now `pub`) instead of stepping to digital zero. 3. **`8effeb79` fix(client,audio): the Deck playback callback ran on our own thread at nice 0** — the PipeWire playback stream connects with `RT_PROCESS` (the graph rendered silence for our node whenever our main-loop thread missed the 5 ms cycle — invisible to every counter); the callback is RT-safe (pre-reserved ring, no logging); new `audio_vitals::PlaybackVitals` atomics on both twins, and the decode thread prints the same `audio playback …` / `audio playback quantum` lines on wall clock (same field names — greps keep working, one logging site for PipeWire and WASAPI); best-effort `setpriority(-10)` on the decode thread. 4. **`f9b5673d` fix(client): the vendored decoder's DPB chatter evicted the whole log ring** — the session's `RingLayer` normalizes `log`-bridge events to their real target (host `log_capture.rs` recipe) and drops `cros_codecs` at DEBUG/TRACE (its WARN+ still lands, `log.*` bookkeeping fields dropped). Tested end to end through the bridge. `Cargo.lock` gains two direct deps already in the graph. ## Not in this PR (documented in the report) Symmetric depth correction in `JitterPolicy` (sync-driven deepening today = `hollow` → the next late packet de-primes a full target — all four clients), rtkit/MMCSS for the client audio threads (Windows client render thread still unboosted; its pinned windows-rs revision could not be compile-checked from the Mac), a session-scoped debounce of library fs-change reconciles (102 in 27 min), and making our PipeWire sink drive its own group so no hardware card can clock the game→punktfunk path. ## Gate - Host (`punktfunk-rust-ci`, amd64): `cargo fmt --check` · `clippy --all-targets -p punktfunk-host -p punktfunk-core -- -D warnings` · plain build · tests — **466 core + 603 host, 0 failed**, non-vacuous. - Client (`pf-gtkflow`): same for `pf-client-core` + `punktfunk-client-session` — **220 + 4 + 1, 0 failed**. - New tests: `gap_histogram_gives_the_shape_and_the_cost`, `infill_threshold_follows_a_clamped_quantum`, `the_head_fade_mirrors_the_tail_fade`, `bridged_decoder_debug_is_dropped_and_the_audio_line_survives`, `counters_accumulate_and_gauges_overwrite` — all confirmed present via `--list`. - Apple/Android untouched. The pacer's inner loop is thread plumbing with no unit test; on-glass verification (a Deck against a lossy host) is owed and the reporter's next canary log is the first data point (`gap_hist=` will be on it, and the Deck bundle will finally carry its audio line).

enricobuehler added 4 commits 2026-08-18 10:29:12 +00:00

feat(host,audio): the capture line said sixty holes and could not say what shape they were ... aa070d1f4a

`gaps=60 max_gap_ms=146` reads the same for sixty 30 ms stalls (a periodic scheduler on the box)
and for fifty-nine 12 ms hiccups plus one outage, and those want different fixes. The 2026-08-17
Skynet log had that ambiguity across all 53 windows — 89–98 % delivered, gap counts alternating
high/low on consecutive 30 s windows, and no way to tell whether the loss was in the counted
holes or below the counter's floor.

- `CaptureStats::observe_gap` is the one accounting behind both feeds (the Linux callback cadence
  and the Windows discontinuity flag, which used to poke the fields directly) and now also buckets
  each hole (<20 / <50 / <100 / >=100 ms — the client-concealment edges) and sums the audio lost.
- Both capture lines print `gap_hist=a/b/c/d missing_ms=`; the sum closes the arithmetic against
  `delivered_pct`, so sub-threshold losses become the visible remainder.
- The Windows loopback READER thread now takes the same `boost_thread_priority(true)` the paced
  sender it feeds has carried since the data-plane QoS work; it ran at normal priority beside it.

fix(host,audio): the pacer's schedule was wall clock, the source was not, and every hole left it further behind ... dc2d946949

The 2026-08-17 Skynet log: 33–72 % of audio departures "late", `max_late_ms` climbing to 99 while
`reanchors` stayed at 0 and `max_spacing_ms` at 13 — a schedule that had fallen behind and stayed
behind, sending frames 5 ms apart against a grid it never advanced for the audio the graph lost.
A missed 2.7 ms cycle or two is below the capture gap counter's floor and below the infill
threshold, so nothing covered it and `pace_due` kept the debt; the next >= 10 ms hole then repaid
it as a burst of (lag + 10) / 5 silence frames back to back. On the client that is a ring drained
one frame per uncompensated loss, then refilled with a burst it has to trim.

- The infill decision looks at the schedule LAG as well as the time since the last chunk: a
  schedule `after()` behind with no audio in hand is owed cover exactly like a hole that long.
  Lag is bounded at that; the debt burst is gone; `late` beyond that band is this thread's own
  scheduling, which is what WP-C built the counter for.
- `after()` follows the real quantum (`InfillPolicy::note_quantum`, in capture_policy): one chunk
  plus one frame, never less than two frames. Bit-identical at a frame-sized quantum; on a VM's
  clamped 1024-frame buffer the old flat 10 ms sat in the middle of a legitimate cycle, so a chunk
  a couple of ms late would have been covered and left a frame of surplus behind for good.
- A slot whose remaining backlog exceeds one chunk plus one frame sends a second frame in the same
  slot (at most two per slot). Left alone a fast source clock could only ever grow the backlog —
  one frame per slot, forever — five milliseconds of host latency every fifty seconds at 100 ppm.
- Holes no longer open on a step to digital zero and close mid-waveform: the first infill frame
  fades the partial (or the last real frame's head) out over 1 ms and the first real frame after
  the hole fades in over the same raised cosine (`pcm::raised_cosine_tail/head`, now public).

fix(client,audio): the playback callback ran on our own thread at nice 0, and the graph did not wait for it ... 8effeb792a

The desktop client's PipeWire playback stream connected without `RT_PROCESS`, so `process()` ran
on the main-loop thread at ordinary priority: PipeWire's data loop signalled it, and if this thread
was not scheduled inside the 5 ms cycle the graph rendered silence for our node and moved on — an
underrun neither our counters nor the ring ever saw, because by the time we ran the ring was full
and the callback drained normally. On a Steam Deck decoding 1440p120 alongside, that is a real and
invisible source of clicks. The host's own PipeWire stream nodes have run `RT_PROCESS` since they
were written.

- The stream connects with `RT_PROCESS`; the ring is pre-reserved (hard cap + the whole pump
  channel, from the resolved format), so `extend` never reallocates on the realtime loop; the
  callback formats nothing.
- New `audio_vitals::PlaybackVitals` — atomics both twins publish from their device callback; the
  decode thread prints the same `audio playback buffer_ms= target_ms= underruns= drift_sheds=
  plc_ms=` line (plus the one-shot `audio playback quantum`) on wall clock, so a field-log grep
  keeps working and the WASAPI twin's line comes from the same site.
- The decode thread takes a best-effort nice −10 on Linux (rtkit is the follow-up).

fix(client): the vendored decoder's DPB chatter evicted the whole log ring in three seconds ... f9b5673d78

The 2026-08-17 Steam Deck bundle read `… 2037456 older lines evicted from the ring …` followed by
3.5 s of `Retaining pic POC` / `Stored picture` / `find_short_term_ref_by_poc` lines: cros-codecs
DEBUG-logs its DPB bookkeeping a dozen lines per frame, the ring layer captured every target at
DEBUG, and 4 096 lines last three seconds at 120 fps. The 27-minute session — and the 10 s
`audio playback buffer_ms= underruns=` line three investigation rounds had been waiting for —
was gone. A field ring a healthy decoder can flush is worse than none: it looks like diagnostics
and carries none.

The ring layer now normalizes `log`-bridge events to their real target (the host's
`log_capture.rs` recipe) and drops DEBUG/TRACE from `cros_codecs`; its WARN+ still lands, and the
bridge's `log.*` bookkeeping fields no longer ride every line. Tested end to end through the
bridge. `Cargo.lock` gains the two direct deps (already in the graph).

enricobuehler merged commit c7be3bb9d0 into main 2026-08-18 10:41:05 +00:00

enricobuehler deleted branch worktree-audio-stutter-stack-audit 2026-08-18 10:41:06 +00:00

enricobuehler referenced this issue from a commit 2026-08-18 15:01:55 +00:00

feat(client): give the audio decode, pad-audio and WASAPI threads real priority — the Realtime portal in a flatpak, rtkit outside, MMCSS on Windows

enricobuehler referenced this pull request 2026-08-18 15:02:30 +00:00

Audio follow-ups: the jitter ring deepens by inserting instead of de-priming, client audio threads get real priority, fs-change syncs are rate-capped #303

Sign in to join this conversation.

Reviewers

No Reviewers

Labels

No items

No labels

Milestone

No items

No Milestone

Projects

Clear projects

No projects

Assignees

Clear assignees

FernandoMX HitFrostbite enricobuehler (Enrico Bühler) kszlim luxus nannku neoney sassycrown

No Assignees

1 Participants

Notifications

Subscribe

Due Date

No due date set.

Dependencies

No dependencies set.

Reference: unom/punktfunk#292