Commit 077e1db1 by PLN (Algolia)

perf(audio): the rig was reading samples off disk while playing

Went looking for latency to shave in the PipeWire quantum. The quantum was not
the problem.

preload.scd did not exist on this box. start_and_midi.scd:259 tests for it with
File.exists and silently takes the other branch -- 'no preload.scd, lazy-loading
samples on demand.' Driving rose_rouge headlessly for three minutes logged 46
'reading soundfile as needed' lines, one every 5-12s, each a disk read landing on
the audio thread; the SuperCollider node's pw-top W/Q hit 1.300 at the stock 1024
and 1.390 at 512, i.e. missing its deadline regardless of buffer size.
check-preload.sh named it exactly: '60 bank(s) would be read from DISK on first
play (crackle, mid-transition)' -- the same sentence its own header attributes to
a crackle that debuted at a venue.

Generated with check-preload.sh --fix (60 banks, 16 tracks) and verified at the
next boot: 'PRELOAD: 60/61 banks OK in 2.6 s'. The mechanism was never broken;
gig-up.sh already regenerates the plan and the checker already exits non-zero.
gig-up.sh had simply never been run on this box.

Re-running the identical load after the fix left 29 lazy reads, ALL of them the
rose bank -- because rose_rouge is not in setlist_opal2026.txt. Zero of the 60
preloaded banks lazy-loaded, so the plan works; it warms the OPAL set while the
track this box actually plays sits outside it. Logged, with two more findings
from the same boot: preload's own COUNT MISMATCH banner firing on a
sixty-second-old plan, and three global mi-UGens FX synthdefs failing to load at
every boot while rig-doctor's mi-ugens check stays green.

Adds tools/latency-lens.py, which implements the documented quantum method
(lowest quantum holding zero xrun delta and max W/Q under 0.75) against pw-top,
sets clock.force-quantum at runtime and restores it, and never edits a config.
It refuses to run unless the default sink is muted and re-checks that every
second for the whole run: a valid quantum test needs the real hardware device
driving the graph but does not need the speakers.
parent b9564095
...@@ -4,6 +4,83 @@ Sprint entries, newest first. Player-facing: what changed about *playing*, not ...@@ -4,6 +4,83 @@ Sprint entries, newest first. Player-facing: what changed about *playing*, not
about the code. Task IDs reference the L'Armada board; `n/a` where the work was about the code. Task IDs reference the L'Armada board; `n/a` where the work was
unplanned (which, on a gig night, is most of it). unplanned (which, on a gig night, is most of it).
## Sprint 6 — 2026-09-07 · the crackle that was waiting at the venue
Went looking for latency to shave. Found that the thing making the rig miss its
deadline was not the buffer size at all — it was reading samples off the disk
while playing, because the plan that prevents exactly that had never been
generated on this laptop.
### Fixed
- **60 banks no longer read off disk mid-set** (n/a). `preload.scd` did not
exist here, and `start_and_midi.scd` tests for it with `File.exists` and
quietly takes the other branch — *"no preload.scd — lazy-loading samples on
demand."* Driving `rose_rouge` headlessly logged **46** `reading soundfile as
needed` lines in three minutes, one every 5-12 seconds, each a disk read on
the audio thread. `check-preload.sh` named it exactly: *"60 bank(s) would be
read from DISK on first play (crackle, mid-transition)"* — the same sentence
its own header attributes to a crackle that "debuted at the venue". Generated
with `check-preload.sh --fix`: 60 banks, all 16 setlist tracks.
The mechanism was never broken — `gig-up.sh` already regenerates the plan and
the checker already exits non-zero — **`gig-up.sh` had simply not been run on
this box since the setlist grew.** Which is the real lesson: the only thing
that keeps a generated artifact fresh is the one path nobody had taken yet.
### Found, not yet fixed
- **The plan is now fresh and pointed at the wrong set** (n/a). Re-running the
identical load after the fix still logged 29 lazy reads — and every one was
the `rose` bank, because `rose_rouge` is not in `setlist_opal2026.txt`. Zero
of the 60 preloaded banks lazy-loaded, so the mechanism is provably working:
it is warming the 16-track OPAL set while the track this box actually plays
sits outside it. A freshness check that compares the plan to the setlist
cannot catch that, because the plan and the setlist agree — it is the setlist
that has drifted from reality.
- **Preload cries wolf on a plan sixty seconds old** (n/a): `60/61 banks OK`
followed by its own `PRELOAD COUNT MISMATCH — whitelist is STALE, regenerate
it`. A warning that fires when nothing is wrong is a warning nobody reads on
the night it is right.
- **Three global FX synthdefs fail at every boot** (n/a) — `global_mi_verb2`,
`global_mi_clouds2`, `global_mi_ripples2`, all `SynthDef not found`. Any send
routed to the mi-UGens global buses is silence. `rig-doctor`'s mi-ugens check
is green, so it is testing that the plugins exist rather than that the
synthdefs load.
### Added
- **`tools/latency-lens.py`** (n/a) — choose the PipeWire quantum by
measurement. Nothing had ever chosen 1024; there is no PipeWire config on
this box at all, so it is the raw upstream default, which belongs to
mixing/mastering rather than live monitoring. The lens implements the
documented method (lowest quantum holding zero xrun delta and max W/Q below
0.75), sets `clock.force-quantum` at runtime and restores it, and never edits
a config — `--print-config Q` prints the drop-in for when a choice is made.
It refuses to run unless the default sink is muted, **and keeps checking every
second for the whole run**, because a valid test needs the real hardware
device driving the graph but does not need the speakers. Written to a
constraint PLN gave at midnight: a friend was asleep in the flat.
- **`rig-doctor` should FAIL on an absent or stale preload plan** — logged in
`backlog.md`, not built. One `check-preload.sh` call, exactly like the
`parvagues-protect --check` fix, and it stands between a cold boot and a
crackle.
### Doctrine
- **Measure the thing, then check what you measured.** The quantum sweep's
first run came back with three clean-looking rows and a `no-data` verdict,
because `WATCH` listed the PROCESS name `scsynth` while the PipeWire node is
called `SuperCollider`. Every dwell had sampled only the ALSA device.
`gig-log.py` already had the right names in `XRUN_NODES`; the tool now keeps
them in step and prints which nodes it actually sampled, so absent data
cannot look like good data.
- **An error is not a negative.** The mute guard read a transient wireplumber
`Translate ID error` as "the sink was unmuted" and aborted a six-minute sweep
on candidate three, naming a cause that had not happened. It now separates
"definitely not muted" from "could not tell" — same action, different
sentence — and retries once.
- **Read the exit code of the command, not of the pipe.** `check-preload.sh` was
briefly accused of exiting 0 while reporting STALE, which would have made
gig-up's auto-fix dead code. It exits 1. The 0 belonged to the `tail` on the
end of the pipeline. Third time in two days that a measurement bug wore the
costume of a code bug — see also `grep -c` printing 0 and exiting 1.
## Sprint 5 — 2026-09-06 (latest) · nothing restarts a boot that is going fine ## Sprint 5 — 2026-09-06 (latest) · nothing restarts a boot that is going fine
Sprint 4 measured the guard and found it fidgeting. Measuring it also turned up Sprint 4 measured the guard and found it fidgeting. Measuring it also turned up
......
...@@ -2110,7 +2110,109 @@ scattered through this file resolve locally. ...@@ -2110,7 +2110,109 @@ scattered through this file resolve locally.
**Still to verify:** reinstall and watch a restart re-protect on its own, which **Still to verify:** reinstall and watch a restart re-protect on its own, which
is the only test that proves it (`systemctl --user restart parvagues-sc`, then is the only test that proves it (`systemctl --user restart parvagues-sc`, then
`parvagues-protect --check` — expect `oom:200->-1000` naming the NEW pid). `parvagues-protect --check` — expect `oom:200->-1000` naming the NEW pid).
- 🔴 **`preload.scd` did not exist on the XPS24 — 60 banks would have been read
off disk mid-set.** Found 2026-09-07 while trying to measure the quantum, and
it is the same failure `tools/check-preload.sh`'s header calls out as having
"debuted as a crackle at the venue" — except on xps22 the plan existed and
warmed the wrong list, while here there was no plan at all.
`start_and_midi.scd:259` tests `File.exists("preload.scd")` and silently
takes the other branch: *"preload: no preload.scd — lazy-loading samples on
demand."*
**Measured, not inferred.** Driving `rose_rouge` headlessly for ~3 min logged
**46** `reading soundfile as needed` lines — `rose:28.0`, `rose:29.0`,
`rose:30.0`, one every 5-12 s, each one a disk read landing on the audio
thread. In the same window the SuperCollider node's `pw-top` **W/Q reached
1.300 at the rig's stock 1024** and 1.390 at 512, i.e. exceeding its deadline
regardless of quantum. `check-preload.sh` then said it plainly: *"60 bank(s)
would be read from DISK on first play (crackle, mid-transition)"*.
**Fixed by running `tools/check-preload.sh --fix`** — 60 banks, all 16
setlist tracks, 7.5 KB, gitignored (correctly, it is generated). Verified at
the next boot: `preload: warming the set's samples…` /
`=== PRELOAD: 60/61 banks OK in 2.6 s ===`.
- 🔴 **The preload plan is fresh and aimed at the wrong set.** Re-running the
same load after the fix still logged 29 lazy reads — and **all 29 were the
`rose` bank**, because `rose_rouge` is NOT in `armada/setlist_opal2026.txt`.
Zero of the 60 preloaded banks lazy-loaded, so the mechanism is provably
working; it is warming the 16-track OPAL set while the track this box has
actually been playing (see the rig-state memory) is outside it.
This is `check-preload.sh`'s own documented failure one layer up: there, the
plan was stale because two tools disagreed about the setlist (10 vs 13
tracks). Here the plan matches its setlist exactly and **the setlist is stale
relative to what gets played**. A freshness check that compares the plan to
the setlist cannot see this — it needs to compare against what is actually
loaded. Cheapest honest fix: add current material to the setlist (or a
second "current" list the generator also reads), then regenerate.
- **Preload reports `60/61` and its own `PRELOAD COUNT MISMATCH — whitelist is
STALE, regenerate it`** on a plan generated sixty seconds earlier. So either
the generator counts one bank the server cannot load, or the two count
different things. Worth ten minutes: the mismatch banner is a real signal that
currently cries wolf on a fresh plan, and a warning that fires when nothing is
wrong is a warning nobody reads on the night it matters.
- **Three global FX synthdefs are missing at every boot**: `global_mi_verb2`,
`global_mi_clouds2`, `global_mi_ripples2` — `*** ERROR: SynthDef ... not
found` / `FAILURE IN SERVER /s_new SynthDef not found`, seen 2026-09-07 on a
clean boot. These are the mi-UGens global effect buses, so any track routing
to them gets silence from that send. `rig-doctor`'s mi-ugens check passes,
which means it is checking that the plugins are present rather than that the
synthdefs load — the same presence-versus-function gap as everywhere else this
week.
**The mechanism was never broken**: `gig-up.sh:182` already calls the checker
and auto-fixes on a non-zero exit, and the checker does exit 1 correctly.
`gig-up.sh` simply has not been run on this box since the setlist grew. So
the gap is not the code, it is that the gig-up path is the only thing that
regenerates the plan and nothing else notices. **`rig-doctor` should FAIL on a
stale-or-absent preload plan** — it is 46 disk reads and a venue crackle away
from being a real preflight item, and it costs one `check-preload.sh` call,
exactly like the `parvagues-protect --check` fix.
- **Block size 1024 (~21 ms)** — high for livecoding. Worth tuning the PipeWire quantum. - **Block size 1024 (~21 ms)** — high for livecoding. Worth tuning the PipeWire quantum.
**Cannot be answered until preload is warm** — see the entry above. Both
candidates measured on a cold cache rejected (1024: W/Q 1.300, +6,982 ERR in
60 s; 512: W/Q 1.390, +17,348), and W/Q > 1 at the *stock* setting means the
measurement was reading disk stalls, not DSP headroom. Re-run after a warm
boot before drawing any conclusion about quantum.
**Groundwork done 2026-09-07: `tools/latency-lens.py`.** Nothing had ever
chosen 1024 — there is no PipeWire config on this box at all
(`~/.config/pipewire/` and `/etc/pipewire/pipewire.conf.d/` both absent), so
it is the raw upstream default, which current guidance places in the
mixing/mastering bracket (no live input); live monitoring sits near 256
(5.3 ms period, ~10.7 ms round trip). It only became worth measuring once
scsynth reliably ran at SCHED_FIFO/90 — the guidance is blunt that without RT
scheduling every other tuning is marginal, and until `a828d5f` protect was
handing scsynth back at `SCHED_OTHER/0`.
The lens implements the documented method rather than a guess: accept the
LOWEST quantum holding **ERR delta 0** and **max W/Q < 0.75** under a
representative load, sampled from `pw-top -b`. It sets `clock.force-quantum`
at runtime and restores it; it never edits a config (`--print-config Q`
prints the drop-in to write when a choice is actually made).
**It refuses to run unless the default sink is muted, continuously.** A valid
quantum test needs the real hardware device driving the graph (a null sink is
driven by a software timer and answers far too optimistically), but it does
not need the speakers: mute sits downstream of all DSP. The mute is
re-checked ~1/s for the whole run and the sweep dies the instant it stops
holding — because a one-shot check is a snapshot, not a guarantee, and this
was proven twice in ten minutes (see the learnings below).
**Still to do:** the real acceptance run — `--dwell 600`, UMC202HD plugged
in, Ardour recording. USB has its own floor and the gig path is the UMC, so
no number measured on internal audio should be trusted for a venue.
- **Nothing on this rig counts SuperCollider `late` messages**, and they are the
single best timing-health signal a Tidal rig has. 136 of them on 2026-09-06
went unnoticed: `gig-log` records thermals, freq, cpu, gear, xrun deltas,
MIDI, track and eval — not `late`. Found only by grepping the journal by hand.
They came in **two bursts** (64 at 19:58, 72 at 20:03), values *decaying*
8.1 s → 0.65 s like a drained backlog, not the steady trickle that means
"latency too low". Both bursts sit against SC restarts, and the 20:03 one is
the watchdog bug fixed in `b956409`, caught in the act:
`20:03:35 scsynth GONE (3 polls) … restarting (1 prior in window)` six
seconds into a healthy boot. `late` belongs in gig-log's `s` record as a
delta, next to the xruns.
- **`s.latency = 0.3` is probably padding for a cause that was misdiagnosed.**
`start_and_midi.scd:349`, comment "increase this if you get late messages",
history `1` → `0.3` (`d008a31`) and never revisited. SC's documented default
is 0.2, and 0.3 s is what sits between ctrl+enter and hearing the change. The
documented reason to pad it — late messages — was two restart bursts, not
insufficient latency. **Not changed blind**: walking it down wants the `late`
counter above so the rollback signal is visible, plus PLN's ears. Cheap and
reversible once both exist.
- **No ld.so.conf.d preference for PipeWire's libjack**, so `libjack.so.0` resolves to - **No ld.so.conf.d preference for PipeWire's libjack**, so `libjack.so.0` resolves to
jackd2's. `pw-jack` works around it per-app; a system-wide preference would also make jackd2's. `pw-jack` works around it per-app; a system-wide preference would also make
qjackctl show the graph the rig is actually in, instead of an empty jackd2 one. Needs qjackctl show the graph the rig is actually in, instead of an empty jackd2 one. Needs
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment