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

4 Commits

Author	SHA1	Message	Date
enricobuehler	f9b5673d78	fix(client): the vendored decoder's DPB chatter evicted the whole log ring in three seconds ... 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).	2026-08-18 11:14:08 +02:00
enricobuehler	8effeb792a	fix(client,audio): the playback callback ran on our own thread at nice 0, and the graph did not wait for it ... 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).	2026-08-18 11:13:56 +02:00
enricobuehler	dc2d946949	fix(host,audio): the pacer's schedule was wall clock, the source was not, and every hole left it further behind ... 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).	2026-08-18 11:13:44 +02:00
enricobuehler	aa070d1f4a	feat(host,audio): the capture line said sixty holes and could not say what shape they were ... `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.	2026-08-18 11:13:25 +02:00