Two unrelated defects were hiding behind one audio metric #258
No Assignees
Notifications
Due Date
No due date set.
Dependencies
No dependencies set.
Reference: unom/punktfunk#258
Reference in New Issue
Block a user
delivered_pct < 100has been the audio-stutter campaign's only signal. It conflates two mechanisms that want opposite responses, and no field in the log could separate them.A — absence. Our capture node sits in PipeWire
Paused. Reproduced live on.181during a real game session, on canaryg4ee09522(the commit this branched from): spans of 4.5 s, 10.8 s and 16.2 s, reportinggaps=0is correct and deliberate — a stream that is not scheduled fires no callbacks, anda_paused_span_is_not_scoredpins that. But the outage did not vanish: the reporting window is flushed from the process callback, so a pause stretches the window and dilutes the percentage by exactly the time we were absent. This one is benign (peak_db=-120.0, digital silence — nothing was playing), and it is fleet-wide: ~38–41 s at every Skynet session start, ~96 s on AVALON.B — starvation. Node continuously
Streaming, handing over 5–8 % less than real time through loud content. Skynet-only: AVALON on 0.28.0 — same module, same negotiated quantum, same compositor, a harder workload (4K120/8 ch) — holdsdelivered_pct=100for 328 s straight, while Skynet never reaches 100 once in 46 consecutive windows, uncorrelated with content (r=−0.05 vs rms).Neither is evidence of the v0.25 audio rework. There is still no pre-0.25 log, so the reporter's steer is not refuted — but nothing measured here points at the client A/V sync or the host pacing rework.
What is in the PR
2563041e— make the line answer the question it invites.pauses/paused_msbeside the percentage they explain.gapskeeps its narrow meaning (holes inside a running stream), 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.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. It now reportssent/infilled/late/max_late_ms/max_spacing_ms/reanchorson the same 30 s window as capture, so the two read as a pair. Notereanchors: the pacer forgives accumulated debt silently, which is exactly the event that leaves no trace and then gets blamed on the network.7c964e95— the rtkit boost was applied to a thread that does not run the capture callback.The comment claimed
process()runs on our mainloop thread. It does not: we passRT_PROCESS, so libpipewire runs it on a data loop it owns and schedules. Measured in one live host process:That is why "priorities engaged yet stutter persists" was a dead end. The callback now reports its own policy/priority/nice once per open, so every future log states what the audio path actually runs as instead of what we asked for elsewhere. The boost is kept — that thread still dispatches state and format events, and it is the capture thread on the legacy
PUNKTFUNK_STREAM_SINK=0path.Deliberately not attempted: 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, where a nice boost would be inert.
Not included, on purpose
node.always-process. Its cost is now measured rather than feared (pw-topunder load: our sink ERR=0, ~20 µs/cycle = 0.33–0.46 % of one core, which answers the R5 objection). It is still not shipped: it would make the wire carry continuous silent Opus, quietly reversing #249's consideredInfill::Quietdecision — and withpaused_msshipped, the ambiguity that motivated it is already gone.Windows keeps its own field set. Its capture model differs (WASAPI loopback stops delivering while the endpoint idles, so its
delivered_pctis partly a content metric), and zero-valued fields would imply it had measured something it did not.Gate
amd64 CI container:
cargo fmt --all --check,cargo clippy --all-targets -p punktfunk-host -p pf-frame -- -D warnings,cargo test -p pf-frame, and the fullcargo test -p punktfunk-hostat 560 passed. Non-vacuity confirmed (Compiling punktfunk-hostpresent in every run).The single full-suite 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 its documented discriminator, and nothing here touches it.Four new capture-policy tests plus a
pf-framenon-vacuity test that the scheduler introspection returns a policy the kernel could actually have named.Still open
Skynet's mechanism B root cause is not fixable blind and does not reproduce on any box here. The three new lines are designed to close it from a single field log: a non-realtime capture callback at a 2.7 ms quantum is exactly what a Wine shader storm deschedules for ~30 ms at a time, and if it instead reads
SCHED_RRthe graph itself is dropping cycles and the answer is on the box.On-glass verification of the new lines is owed — they compile and their policy is unit-tested, but no host has run them.
Full writeup:
~/Downloads/punktfunk-audio-stutter-findings-20260815-part2.md.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).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.