Two unrelated defects were hiding behind one audio metric #258

Merged

enricobuehler merged 2 commits from worktree-audio-stutter-fixes into main 2026-08-15 20:15:34 +00:00

Conversation 0 Commits 2 Files Changed 4

+477 -46

2 Commits

Author	SHA1	Message	Date
enricobuehler	7c964e95c6	fix(host,audio): the rtkit boost was applied to a thread that does not run the capture callback ... The comment above it asserted "the stream's `process` callbacks run ON this mainloop thread (we never hand PipeWire a separate data loop)". We do: the stream is created with `RT_PROCESS`, so libpipewire runs `process()` on a data loop it creates and schedules itself. Measured in one live host process on 2026-08-15: punktfunk-pw-au SCHED_OTHER nice 0 <- the thread we boost data-loop.0 SCHED_RR prio 20 <- the thread running process() This is not a stale-comment nit. #232 shipped the rtkit boost to answer a field report of audio stutter, its success line was read as evidence that the capture callback had been prioritised, and the follow-up round concluded priorities were "engaged but insufficient" — when they had never been applied to the thread in question. Whether the capture callback is realtime decides whether a Wine shader storm can deschedule it for tens of milliseconds at a 2.7 ms quantum, which is the exact shape of the one field signature still unexplained (~2 stalls/s of ~30 ms with the node reporting itself continuously Streaming). So the assumption is replaced by a measurement rather than a guess about which thread to boost: - `pf_frame::thread_qos::current_thread_sched()` reports the calling thread's policy, RT priority and nice. Three by-value syscalls, no allocation and no blocking, so it is safe to call from an RT callback. - The capture callback reports its own scheduling once per open. Every future field log now states what the audio path actually runs as, instead of what we asked for somewhere else. The boost itself is kept: this thread still dispatches state and format events, and it IS the capture thread when `PUNKTFUNK_STREAM_SINK=0` selects the legacy monitor path. Deliberately not attempted here: boosting the data loop. rtkit is a blocking D-Bus call and must never run inside an RT audio callback, and on the one host that could be measured PipeWire already gives that thread SCHED_RR/20 — a nice boost would be inert. Ship the instrument first; a host that reports SCHED_OTHER here is the evidence that would justify the plumbing. Gated in the amd64 CI container: fmt, clippy -D warnings on punktfunk-host and pf-frame, pf-frame tests (incl. a non-vacuity test that the introspection returns a policy the kernel could have named), and the full punktfunk-host suite at 560 passed. The one failure, mgmt::tests::local_summary_is_loopback_only_and_ non_sensitive, is the recorded process-global parallel-test race: it passes when run alone, which is the documented discriminator, and it is untouched by this.	2026-08-15 20:13:14 +02:00
enricobuehler	2563041e88	feat(host,audio): a 16-second outage and a starved stream reported the same numbers ... Measured on a live host running this commit's parent: our PipeWire capture stream spent 16.2 s of one window in `Paused`, and the line said delivered_pct=63 gaps=0 max_gap_ms=0 Every number is correct. `gaps` scores inter-callback deltas and a stream that is not scheduled fires no callbacks, so there is nothing to score — that is deliberate, and `a_paused_span_is_not_scored` pins it. But the outage did not vanish; it moved into `delivered_pct`, because the reporting window is flushed from the process callback and therefore STRETCHES by exactly the time we were absent. The only explanation lived in the state DEBUG lines, which a field journal at INFO does not carry. So a shortfall had two possible causes and no way to tell them apart: a sink nobody was rendering into (benign — the 2026-08-15 logs show ~40 s of it at every session start, at peak_db=-120.0, i.e. digital silence), or a capture path losing real audio under load (Skynet, 5-8 % through loud gameplay). Those want opposite responses and cost days of investigation to separate by hand. Three changes, one theme — make the line answer the question it invites: - `pauses` / `paused_ms` beside the percentage they explain. `gaps` keeps its narrow meaning (holes inside a running stream); absence is counted separately, because a burst of sub-10 ms holes is a scheduling problem on the box and a multi-second pause is our node not being in the graph at all. - The quantum now tracks what the graph is actually handing us instead of latching the first callback of the open. A graph re-plans whenever anything else on the box asks for a different latency, and the stale value silently corrupted the very threshold gaps are scored against. A new size must survive three callbacks before it is believed, so one short buffer cannot move it. - `audio egress` — the send path had no periodic metric of any kind. Across five field logs it emitted 14 lines, all the same session banner, which made "the host paces audio badly" unfalsifiable and left it on the suspect list forever. It now reports sent/infilled/late/max_late_ms/max_spacing_ms/reanchors on the same 30 s window as capture, so the two read as a pair: holes at the tap with clean departures means the host delivered everything it had. Note `reanchors` in particular — the pacer forgives accumulated debt silently, and that is precisely the event that leaves no trace and then gets blamed on the network. Windows keeps its own field set; its capture model differs (loopback stops delivering while the endpoint idles) and zero-valued fields would imply it had measured something it did not. Gated in the amd64 CI container: fmt, clippy -D warnings, 18 capture-policy tests (4 new, plus the pause pair sitting next to the test that pins the blindness they answer).	2026-08-15 20:05:10 +02:00