diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 452abdd..c7c1de0 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -78,6 +78,12 @@ jobs: with: submodules: recursive + # The ALSA headers, so the Linux legs build async's hardware bridge + # (examples/alsa_bridge.cpp, the roadmap's A11) and run its checks. + - name: Install ALSA headers + if: runner.os == 'Linux' + run: sudo apt-get update -q && sudo apt-get install -y -q libasound2-dev + - name: Configure env: CC: ${{ matrix.cc }} diff --git a/.github/workflows/style.yml b/.github/workflows/style.yml index 257439d..2009f76 100644 --- a/.github/workflows/style.yml +++ b/.github/workflows/style.yml @@ -47,8 +47,9 @@ jobs: with: submodules: recursive - name: Install tools - run: sudo apt-get update && sudo apt-get install -y clang-tidy-18 cmake python3 - # Every engine with its tests and examples, plus every engine's icount + run: sudo apt-get update && sudo apt-get install -y clang-tidy-18 cmake python3 libasound2-dev + # Every engine with its tests and examples (libasound2-dev brings async's + # ALSA bridge in, the roadmap's A11), plus every engine's icount # workloads (the one family option builds them all). The async workloads # joined the gate with the roadmap's A2; the comparison workloads # (cmp_main.cpp, TAP_SR_ICOUNT_COMPARE) are not configured here. diff --git a/async/docs/HARDWARE_TESTING.md b/async/docs/HARDWARE_TESTING.md index 95d379b..0376745 100644 --- a/async/docs/HARDWARE_TESTING.md +++ b/async/docs/HARDWARE_TESTING.md @@ -44,11 +44,42 @@ stream to a file and analyze it offline with the notebook tooling machinery) — the clocks are real even if the signal never goes analog. [`examples/alsa_bridge.cpp`](../examples/alsa_bridge.cpp) (built as -`tap_sr_async_alsa_bridge` when ALSA is found) implements this harness: `--csv` logs -the per-second `status()` telemetry for plotting the ppm trace, `--dump` -captures the post-ASRC float stream for the offline analysis above, and -`--tone ` substitutes a synthetic sine paced by the input device's real -clock when the analog path is not trusted. +`tap_sr_async_alsa_bridge` when ALSA is found) implements this harness: + +- **`hw:` devices only.** `--in` and `--out` are required and must name + `hw:` devices; the bridge refuses `default`, `plughw:` and every other + plugin device before opening anything. On a Pi, `default` routes through + PipeWire and its own resampler, and the bridge would measure that + converter's clock instead of the dongle's crystal. +- **`--csv `** writes the per-second record: + - the converter's `status()`; + - `CLOCK_MONOTONIC_RAW`; + - each device's cumulative frame count, from its thread; + - each device's ALSA xrun count (`-EPIPE`), kept apart from its other + recoveries; + - where the driver provides one, each device's last hardware pointer + update with its own timestamp (`snd_pcm_htimestamp`, on the same raw + clock), which carries no scheduling jitter. +- **[`examples/alsa_bridge_report.py`](../examples/alsa_bridge_report.py) + analyses that record.** It regresses each device's frames against time + to get the two crystals' rates and their true offset in ppm, from the + thread counts and from the hardware timestamps. It compares that offset + with the servo's mean while locked, and states the ppm wobble and the + FIFO's breathing (standard deviation and peak to peak) and the final + discontinuity counts. `--plot` draws the ppm and fill traces (matplotlib). + Its `--self-test` checks the arithmetic on a synthetic hour, as + `async.Examples.AlsaBridgeReportSelfTest`. +- **`--rt`** runs both audio threads `SCHED_FIFO` with every page locked + (`mlockall`), and fails rather than measuring without them. +- **`--dump`** captures the post-ASRC float stream for the offline analysis + above. +- **`--tone `** substitutes a synthetic sine paced by the input + device's real clock when the analog path is not trusted. + +The Linux CI legs install `libasound2-dev`, so the bridge is built, +clang-tidy-clean and checked to refuse a plugin device +(`async.Examples.AlsaBridgeRefusesPluginDevices`) on every PR. It still +needs two dongles to run. ## Setup 2 — Pi (Cortex-A) + Raspberry Pi Pico 2: the M33 target on real silicon @@ -101,9 +132,9 @@ emulation work predicted. What exists and what remains: -- **Setup 1**: shipped — `examples/alsa_bridge.cpp` (see above). Still - missing: a small script to plot the `--csv` ppm trace and run the - notebook analysis over a `--dump` capture. +- **Setup 1**: shipped. `examples/alsa_bridge.cpp` and + `examples/alsa_bridge_report.py` are described above. Still missing: a + script that runs the notebook analysis over a `--dump` capture. - **Setup 2**: shipped — `examples/pico2_cyccnt/` (cycle measurement) and `examples/pico2_dualcore/` (dual-core deployment), both building flashable UF2s; the measured numbers await a physical Pico 2. diff --git a/async/examples/CMakeLists.txt b/async/examples/CMakeLists.txt index e8d1364..05f2098 100644 --- a/async/examples/CMakeLists.txt +++ b/async/examples/CMakeLists.txt @@ -15,6 +15,22 @@ if(ALSA_FOUND) tap_sr_async_warnings ALSA::ALSA Threads::Threads) + # No hardware on CI: the measurement's guard is what can be checked there. + # A plugin device must be refused before anything is opened. + add_test(NAME async.Examples.AlsaBridgeRefusesPluginDevices + COMMAND tap_sr_async_alsa_bridge --in default --out hw:0) + set_tests_properties(async.Examples.AlsaBridgeRefusesPluginDevices PROPERTIES + PASS_REGULAR_EXPRESSION "refusing 'default': only hw: devices" + LABELS async) else() message(STATUS "ALSA not found; skipping tap_sr_async_alsa_bridge example") endif() + +# The bench's analysis (alsa_bridge_report.py): its arithmetic against a +# synthetic run with known rates, wherever Python is. +find_package(Python3 COMPONENTS Interpreter QUIET) +if(Python3_Interpreter_FOUND) + add_test(NAME async.Examples.AlsaBridgeReportSelfTest + COMMAND Python3::Interpreter ${CMAKE_CURRENT_SOURCE_DIR}/alsa_bridge_report.py --self-test) + set_tests_properties(async.Examples.AlsaBridgeReportSelfTest PROPERTIES LABELS async) +endif() diff --git a/async/examples/alsa_bridge.cpp b/async/examples/alsa_bridge.cpp index f230ff7..49c0ef0 100644 --- a/async/examples/alsa_bridge.cpp +++ b/async/examples/alsa_bridge.cpp @@ -16,9 +16,23 @@ // so push() stays paced by the input device's real clock, but the captured // samples are discarded and a synthetic sine is pushed instead — a clean // known signal through real clocks without trusting the dongle's analog path. +// +// The measurement (the roadmap's A11, Block B's bench): only hw: devices are +// accepted, because a plugin device ("default", plughw:, dmix) may route +// through PipeWire or ALSA's own rate converter and the bridge would then +// measure that resampler's clock, not the dongle's crystal. Each device's +// thread counts the frames it moves and the xruns it recovers from, and +// after every transfer records the device's last hardware pointer update +// (snd_pcm_htimestamp, on CLOCK_MONOTONIC_RAW, where the driver provides it). +// The per-second CSV samples all of it beside CLOCK_MONOTONIC_RAW, so +// alsa_bridge_report.py can regress each device's frames against time and +// check the servo's ppm against the crystals' measured ratio. --rt runs both +// audio threads SCHED_FIFO with every page locked (mlockall), and fails +// rather than measuring without them. #include #include +#include #include #include #include @@ -31,12 +45,68 @@ #include #include +#include +#include +#include +#include #include "tap/sr/async/async.h" namespace { std::atomic g_stop{false}; + std::atomic g_failed{false}; // an audio thread could not run as asked (--rt) + + /// Nanoseconds on CLOCK_MONOTONIC_RAW: the clock the CSV samples and the + /// devices' hardware timestamps are taken on, never slewed by NTP. + std::int64_t mono_raw_ns() { + timespec ts{}; + clock_gettime(CLOCK_MONOTONIC_RAW, &ts); + return static_cast(ts.tv_sec) * 1000000000 + ts.tv_nsec; + } + + /// One device's telemetry, written by its own audio thread only and read + /// by the main thread once per second. The hardware position and its + /// timestamp form a pair, published through a sequence counter so the + /// reader never sees one from one update and the other from the next. + struct device_telemetry { + std::atomic frames{0}; ///< frames the thread moved + std::atomic xruns{0}; ///< -EPIPE recoveries (capture overrun, playback underrun) + std::atomic errors{0}; ///< every other recovery (suspend, interrupted call) + + void publish_hw(std::uint64_t hw_frames, std::int64_t hw_ns) { + const std::uint32_t s = m_seq.load(std::memory_order_relaxed); + m_seq.store(s + 1, std::memory_order_relaxed); + std::atomic_thread_fence(std::memory_order_release); + m_hw_frames.store(hw_frames, std::memory_order_relaxed); + m_hw_ns.store(hw_ns, std::memory_order_relaxed); + m_seq.store(s + 2, std::memory_order_release); + } + + /// The last pair, or false while the driver has given no timestamp. + bool read_hw(std::uint64_t& hw_frames, std::int64_t& hw_ns) const { + for (;;) { + const std::uint32_t s0 = m_seq.load(std::memory_order_acquire); + if ((s0 & 1U) != 0) { + continue; + } + hw_frames = m_hw_frames.load(std::memory_order_relaxed); + hw_ns = m_hw_ns.load(std::memory_order_relaxed); + std::atomic_thread_fence(std::memory_order_acquire); + if (m_seq.load(std::memory_order_relaxed) == s0) { + return s0 != 0; + } + } + } + + private: + std::atomic m_seq{0}; + std::atomic m_hw_frames{0}; + std::atomic m_hw_ns{0}; + }; + + device_telemetry g_in_tel; + device_telemetry g_out_tel; void on_sigint(int) { g_stop.store(true, std::memory_order_relaxed); @@ -55,8 +125,8 @@ namespace { } struct cli_args { - const char* in_dev = "default"; - const char* out_dev = "default"; + const char* in_dev = nullptr; + const char* out_dev = nullptr; unsigned rate = 48000; unsigned channels = 2; snd_pcm_uframes_t period = 128; @@ -65,21 +135,24 @@ namespace { const char* dump_path = nullptr; unsigned long seconds = 0; // 0 = run until SIGINT double tone_hz = 0.0; // 0 = pass captured audio through + bool rt = false; }; void usage(const char* prog) { std::printf("usage: %s [options]\n" - " --in ALSA capture device (default \"default\")\n" - " --out ALSA playback device (default \"default\")\n" + " --in ALSA capture device, hw: only (e.g. hw:1,0); required\n" + " --out ALSA playback device, hw: only (e.g. hw:2,0); required\n" " --rate nominal sample rate of both devices (default 48000)\n" " --channels channel count (default 2)\n" " --period frames per ALSA period (default 128)\n" " --latency converter target_latency_frames (default 96)\n" - " --csv append per-second telemetry CSV\n" + " --csv write per-second telemetry CSV (alsa_bridge_report.py)\n" " --dump write post-ASRC interleaved float stream raw\n" " --seconds run time in seconds (default 0 = until SIGINT)\n" " --tone push a synthetic sine paced by the input device's\n" - " clock instead of the captured samples\n", + " clock instead of the captured samples\n" + " --rt run both audio threads SCHED_FIFO with memory locked;\n" + " fail if the system refuses either\n", prog); } @@ -97,30 +170,45 @@ namespace { usage(argv[0]); std::exit(0); } + if (std::strcmp(flag, "--rt") == 0) { + a.rt = true; + continue; + } const char* v = value(i); - if (v == nullptr) + if (v == nullptr) { return false; + } char* end = nullptr; - if (std::strcmp(flag, "--in") == 0) + if (std::strcmp(flag, "--in") == 0) { a.in_dev = v; - else if (std::strcmp(flag, "--out") == 0) + } + else if (std::strcmp(flag, "--out") == 0) { a.out_dev = v; - else if (std::strcmp(flag, "--rate") == 0) + } + else if (std::strcmp(flag, "--rate") == 0) { a.rate = static_cast(std::strtoul(v, &end, 10)); - else if (std::strcmp(flag, "--channels") == 0) + } + else if (std::strcmp(flag, "--channels") == 0) { a.channels = static_cast(std::strtoul(v, &end, 10)); - else if (std::strcmp(flag, "--period") == 0) + } + else if (std::strcmp(flag, "--period") == 0) { a.period = static_cast(std::strtoul(v, &end, 10)); - else if (std::strcmp(flag, "--latency") == 0) + } + else if (std::strcmp(flag, "--latency") == 0) { a.latency = static_cast(std::strtoul(v, &end, 10)); - else if (std::strcmp(flag, "--csv") == 0) + } + else if (std::strcmp(flag, "--csv") == 0) { a.csv_path = v; - else if (std::strcmp(flag, "--dump") == 0) + } + else if (std::strcmp(flag, "--dump") == 0) { a.dump_path = v; - else if (std::strcmp(flag, "--seconds") == 0) + } + else if (std::strcmp(flag, "--seconds") == 0) { a.seconds = std::strtoul(v, &end, 10); - else if (std::strcmp(flag, "--tone") == 0) + } + else if (std::strcmp(flag, "--tone") == 0) { a.tone_hz = std::strtod(v, &end); + } else { std::fprintf(stderr, "%s: unknown option %s\n", argv[0], flag); return false; @@ -130,6 +218,31 @@ namespace { return false; } } + if (a.in_dev == nullptr || a.out_dev == nullptr) { + std::fprintf(stderr, "%s: --in and --out are required\n", argv[0]); + return false; + } + return true; + } + + /// Only a hw: device runs on the dongle's own clock: "default", plughw:, + /// dmix and friends may resample (PipeWire's converter on a Pi, or ALSA's + /// rate plugin), and the bridge would measure that converter instead. + bool is_hw_device(const char* name) { + return std::strncmp(name, "hw:", 3) == 0; + } + + /// SCHED_FIFO for the calling thread, or a failure the run stops on. + bool make_realtime(const char* who) { + sched_param sp{}; + sp.sched_priority = 80; + const int err = pthread_setschedparam(pthread_self(), SCHED_FIFO, &sp); + if (err != 0) { + std::fprintf(stderr, "--rt: %s thread cannot run SCHED_FIFO: %s\n", who, std::strerror(err)); + g_failed.store(true, std::memory_order_relaxed); + g_stop.store(true, std::memory_order_relaxed); + return false; + } return true; } @@ -137,13 +250,15 @@ namespace { snd_pcm_t* pcm = nullptr; snd_pcm_format_t format = SND_PCM_FORMAT_UNKNOWN; snd_pcm_uframes_t period_frames = 0; + snd_pcm_uframes_t buffer_frames = 0; alsa_device() = default; alsa_device(const alsa_device&) = delete; alsa_device& operator=(const alsa_device&) = delete; ~alsa_device() { - if (pcm != nullptr) + if (pcm != nullptr) { snd_pcm_close(pcm); + } } }; @@ -160,46 +275,94 @@ namespace { }; snd_pcm_hw_params_t* hw = nullptr; snd_pcm_hw_params_alloca(&hw); - if ((err = snd_pcm_hw_params_any(dev.pcm, hw)) < 0) + if ((err = snd_pcm_hw_params_any(dev.pcm, hw)) < 0) { return fail("hw_params_any", err); - if ((err = snd_pcm_hw_params_set_access(dev.pcm, hw, SND_PCM_ACCESS_RW_INTERLEAVED)) < 0) + } + if ((err = snd_pcm_hw_params_set_access(dev.pcm, hw, SND_PCM_ACCESS_RW_INTERLEAVED)) < 0) { return fail("set interleaved access", err); + } dev.format = SND_PCM_FORMAT_FLOAT_LE; // native; fall back to S16 + conversion if (snd_pcm_hw_params_set_format(dev.pcm, hw, dev.format) < 0) { dev.format = SND_PCM_FORMAT_S16_LE; - if ((err = snd_pcm_hw_params_set_format(dev.pcm, hw, dev.format)) < 0) + if ((err = snd_pcm_hw_params_set_format(dev.pcm, hw, dev.format)) < 0) { return fail("set format (FLOAT_LE or S16_LE)", err); + } } - if ((err = snd_pcm_hw_params_set_channels(dev.pcm, hw, a.channels)) < 0) + if ((err = snd_pcm_hw_params_set_channels(dev.pcm, hw, a.channels)) < 0) { return fail("set channels", err); + } unsigned rate = a.rate; - if ((err = snd_pcm_hw_params_set_rate_near(dev.pcm, hw, &rate, nullptr)) < 0) + if ((err = snd_pcm_hw_params_set_rate_near(dev.pcm, hw, &rate, nullptr)) < 0) { return fail("set rate", err); + } if (rate != a.rate) { std::fprintf(stderr, "%s '%s': device cannot do %u Hz (offered %u Hz)\n", dir, name, a.rate, rate); return false; } dev.period_frames = a.period; int sub = 0; - if ((err = snd_pcm_hw_params_set_period_size_near(dev.pcm, hw, &dev.period_frames, &sub)) < 0) + if ((err = snd_pcm_hw_params_set_period_size_near(dev.pcm, hw, &dev.period_frames, &sub)) < 0) { return fail("set period size", err); + } snd_pcm_uframes_t buf_frames = 4 * dev.period_frames; - if ((err = snd_pcm_hw_params_set_buffer_size_near(dev.pcm, hw, &buf_frames)) < 0) + if ((err = snd_pcm_hw_params_set_buffer_size_near(dev.pcm, hw, &buf_frames)) < 0) { return fail("set buffer size", err); - if ((err = snd_pcm_hw_params(dev.pcm, hw)) < 0) + } + if ((err = snd_pcm_hw_params(dev.pcm, hw)) < 0) { return fail("hw_params commit", err); + } + dev.buffer_frames = buf_frames; + // Timestamps on every pointer update, on the raw monotonic clock the + // CSV samples; a driver without them leaves snd_pcm_htimestamp at 0. + snd_pcm_sw_params_t* sw = nullptr; + snd_pcm_sw_params_alloca(&sw); + if ((err = snd_pcm_sw_params_current(dev.pcm, sw)) < 0) { + return fail("sw_params_current", err); + } + if ((err = snd_pcm_sw_params_set_tstamp_mode(dev.pcm, sw, SND_PCM_TSTAMP_ENABLE)) < 0) { + return fail("set tstamp mode", err); + } + if ((err = snd_pcm_sw_params_set_tstamp_type(dev.pcm, sw, SND_PCM_TSTAMP_TYPE_MONOTONIC_RAW)) < 0) { + return fail("set tstamp type (MONOTONIC_RAW)", err); + } + if ((err = snd_pcm_sw_params(dev.pcm, sw)) < 0) { + return fail("sw_params commit", err); + } std::printf("%s '%s': %s, %u Hz, %u ch, period %lu, buffer %lu\n", dir, name, snd_pcm_format_name(dev.format), rate, a.channels, static_cast(dev.period_frames), static_cast(buf_frames)); return true; } - void s16ToFloat(const std::int16_t* src, float* dst, std::size_t n) { - for (std::size_t i = 0; i < n; ++i) + /// After a transfer: the device's last hardware pointer update, as the + /// frames the hardware had moved at that instant. Capture: the frames read + /// plus those waiting to be read; playback: the frames written minus those + /// still queued. + void record_hw_position(const alsa_device& dev, device_telemetry& tel, bool capture) { + snd_pcm_uframes_t avail = 0; + snd_htimestamp_t ts{}; + if (snd_pcm_htimestamp(dev.pcm, &avail, &ts) < 0 || (ts.tv_sec == 0 && ts.tv_nsec == 0)) { + return; + } + const std::uint64_t moved = tel.frames.load(std::memory_order_relaxed); + std::uint64_t hw = 0; + if (capture) { + hw = moved + avail; + } + else { + const std::uint64_t queued = dev.buffer_frames > avail ? dev.buffer_frames - avail : 0; + hw = moved > queued ? moved - queued : 0; + } + tel.publish_hw(hw, static_cast(ts.tv_sec) * 1000000000 + ts.tv_nsec); + } + + void s16_to_float(const std::int16_t* src, float* dst, std::size_t n) { + for (std::size_t i = 0; i < n; ++i) { dst[i] = static_cast(src[i]) * (1.0f / 32768.0f); + } } - void floatToS16(const float* src, std::int16_t* dst, std::size_t n) { + void float_to_s16(const float* src, std::int16_t* dst, std::size_t n) { for (std::size_t i = 0; i < n; ++i) { const float x = std::clamp(src[i], -1.0f, 1.0f); dst[i] = static_cast(std::lrintf(x * 32767.0f)); @@ -218,12 +381,28 @@ int main(int argc, char** argv) { std::fprintf(stderr, "%s: rate/channels/period/latency must be nonzero\n", argv[0]); return 2; } + for (const char* dev : {args.in_dev, args.out_dev}) { + if (!is_hw_device(dev)) { + std::fprintf(stderr, + "%s: refusing '%s': only hw: devices are measured (a plugin device such as " + "'default' or plughw: may resample, and the bridge would see that converter's " + "clock, not the crystal's)\n", + argv[0], dev); + return 2; + } + } + if (args.rt && mlockall(MCL_CURRENT | MCL_FUTURE) != 0) { + std::fprintf(stderr, "%s: --rt: mlockall failed: %s (raise RLIMIT_MEMLOCK or run privileged)\n", argv[0], + std::strerror(errno)); + return 1; + } alsa_device in; alsa_device out; if (!open_device(in, args.in_dev, SND_PCM_STREAM_CAPTURE, args) - || !open_device(out, args.out_dev, SND_PCM_STREAM_PLAYBACK, args)) + || !open_device(out, args.out_dev, SND_PCM_STREAM_PLAYBACK, args)) { return 1; + } tap::sr::async::config cfg; cfg.sample_rate_hz = static_cast(args.rate); @@ -240,12 +419,14 @@ int main(int argc, char** argv) { std::FILE* csv = nullptr; if (args.csv_path != nullptr) { - csv = std::fopen(args.csv_path, "a"); + csv = std::fopen(args.csv_path, "w"); if (csv == nullptr) { std::fprintf(stderr, "cannot open CSV file '%s'\n", args.csv_path); return 1; } - std::fprintf(csv, "time_s,state,ppm,fill,underruns,overruns,resyncs\n"); + std::fprintf(csv, "time_s,state,ppm,fill,underruns,overruns,resyncs,mono_raw_ns,in_frames,out_frames," + "in_xruns,out_xruns,in_errors,out_errors,in_hw_frames,in_hw_ns,out_hw_frames," + "out_hw_ns\n"); } std::FILE* dump = nullptr; if (args.dump_path != nullptr) { @@ -259,6 +440,9 @@ int main(int argc, char** argv) { std::signal(SIGINT, on_sigint); std::thread capture([&] { + if (args.rt && !make_realtime("capture")) { + return; + } const std::size_t ch = args.channels; const snd_pcm_uframes_t period = in.period_frames; std::vector raw(period * ch); @@ -270,6 +454,7 @@ int main(int argc, char** argv) { in.format == SND_PCM_FORMAT_S16_LE ? static_cast(raw.data()) : static_cast(buf.data()); const snd_pcm_sframes_t n = snd_pcm_readi(in.pcm, dst, period); if (n < 0) { + (n == -EPIPE ? g_in_tel.xruns : g_in_tel.errors).fetch_add(1, std::memory_order_relaxed); if (snd_pcm_recover(in.pcm, static_cast(n), 1) < 0) { std::fprintf(stderr, "capture failed: %s\n", snd_strerror(static_cast(n))); g_stop.store(true, std::memory_order_relaxed); @@ -278,26 +463,34 @@ int main(int argc, char** argv) { continue; } const auto frames = static_cast(n); - if (frames == 0) + if (frames == 0) { continue; + } + g_in_tel.frames.fetch_add(frames, std::memory_order_relaxed); + record_hw_position(in, g_in_tel, true); if (args.tone_hz > 0.0) { // tone mode: keep the device pacing, swap the payload for (std::size_t f = 0; f < frames; ++f) { const auto v = static_cast(0.5 * std::sin(phase)); phase += dphi; - if (phase >= 2.0 * std::numbers::pi) + if (phase >= 2.0 * std::numbers::pi) { phase -= 2.0 * std::numbers::pi; - for (std::size_t c = 0; c < ch; ++c) + } + for (std::size_t c = 0; c < ch; ++c) { buf[f * ch + c] = v; + } } } else if (in.format == SND_PCM_FORMAT_S16_LE) { - s16ToFloat(raw.data(), buf.data(), frames * ch); + s16_to_float(raw.data(), buf.data(), frames * ch); } asrc.push(buf.data(), frames); // overruns counted by the converter } }); std::thread playback([&] { + if (args.rt && !make_realtime("playback")) { + return; + } const std::size_t ch = args.channels; const snd_pcm_uframes_t period = out.period_frames; std::vector buf(period * ch); @@ -310,8 +503,9 @@ int main(int argc, char** argv) { std::fprintf(stderr, "dump write failed; disabling --dump\n"); dump_failed = true; } - if (out.format == SND_PCM_FORMAT_S16_LE) - floatToS16(buf.data(), raw.data(), period * ch); + if (out.format == SND_PCM_FORMAT_S16_LE) { + float_to_s16(buf.data(), raw.data(), period * ch); + } snd_pcm_uframes_t done = 0; while (done < period && !g_stop.load(std::memory_order_relaxed)) { const void* src = out.format == SND_PCM_FORMAT_S16_LE @@ -319,6 +513,7 @@ int main(int argc, char** argv) { : static_cast(buf.data() + done * ch); const snd_pcm_sframes_t n = snd_pcm_writei(out.pcm, src, period - done); if (n < 0) { + (n == -EPIPE ? g_out_tel.xruns : g_out_tel.errors).fetch_add(1, std::memory_order_relaxed); if (snd_pcm_recover(out.pcm, static_cast(n), 1) < 0) { std::fprintf(stderr, "playback failed: %s\n", snd_strerror(static_cast(n))); g_stop.store(true, std::memory_order_relaxed); @@ -327,6 +522,8 @@ int main(int argc, char** argv) { continue; } done += static_cast(n); + g_out_tel.frames.fetch_add(static_cast(n), std::memory_order_relaxed); + record_hw_position(out, g_out_tel, false); } } snd_pcm_drain(out.pcm); @@ -336,32 +533,59 @@ int main(int argc, char** argv) { const auto t0 = clock::now(); for (unsigned long sec = 1; !g_stop.load(std::memory_order_relaxed); ++sec) { std::this_thread::sleep_until(t0 + std::chrono::seconds(sec)); - if (g_stop.load(std::memory_order_relaxed)) + if (g_stop.load(std::memory_order_relaxed)) { break; - const auto st = asrc.status(); + } + const auto st = asrc.status(); + const std::int64_t now_ns = mono_raw_ns(); + const auto in_xruns = g_in_tel.xruns.load(std::memory_order_relaxed); + const auto out_xruns = g_out_tel.xruns.load(std::memory_order_relaxed); std::printf("t=%6lus state=%-9s ppm=%+8.2f fill=%8.1f under=%llu over=%llu " - "resync=%llu\n", + "resync=%llu xrun in=%llu out=%llu\n", sec, state_name(st.state), st.ppm, st.fifo_fill_frames, static_cast(st.underruns), static_cast(st.overruns), - static_cast(st.resyncs)); + static_cast(st.resyncs), static_cast(in_xruns), + static_cast(out_xruns)); std::fflush(stdout); if (csv != nullptr) { - std::fprintf(csv, "%lu,%s,%.3f,%.2f,%llu,%llu,%llu\n", sec, state_name(st.state), st.ppm, - st.fifo_fill_frames, static_cast(st.underruns), - static_cast(st.overruns), static_cast(st.resyncs)); + std::fprintf(csv, "%lu,%s,%.3f,%.2f,%llu,%llu,%llu,%lld,%llu,%llu,%llu,%llu,%llu,%llu", sec, + state_name(st.state), st.ppm, st.fifo_fill_frames, + static_cast(st.underruns), static_cast(st.overruns), + static_cast(st.resyncs), static_cast(now_ns), + static_cast(g_in_tel.frames.load(std::memory_order_relaxed)), + static_cast(g_out_tel.frames.load(std::memory_order_relaxed)), + static_cast(in_xruns), static_cast(out_xruns), + static_cast(g_in_tel.errors.load(std::memory_order_relaxed)), + static_cast(g_out_tel.errors.load(std::memory_order_relaxed))); + // The hardware pairs; empty fields where the driver gave none. + for (const device_telemetry* tel : {&g_in_tel, &g_out_tel}) { + std::uint64_t hw_frames = 0; + std::int64_t hw_ns = 0; + if (tel->read_hw(hw_frames, hw_ns)) { + std::fprintf(csv, ",%llu,%lld", static_cast(hw_frames), + static_cast(hw_ns)); + } + else { + std::fprintf(csv, ",,"); + } + } + std::fprintf(csv, "\n"); std::fflush(csv); } - if (args.seconds != 0 && sec >= args.seconds) + if (args.seconds != 0 && sec >= args.seconds) { break; + } } g_stop.store(true, std::memory_order_relaxed); capture.join(); playback.join(); - if (csv != nullptr) + if (csv != nullptr) { std::fclose(csv); - if (dump != nullptr) + } + if (dump != nullptr) { std::fclose(dump); + } std::printf("done.\n"); - return 0; + return g_failed.load(std::memory_order_relaxed) ? 1 : 0; } diff --git a/async/examples/alsa_bridge_report.py b/async/examples/alsa_bridge_report.py new file mode 100755 index 0000000..10d4cea --- /dev/null +++ b/async/examples/alsa_bridge_report.py @@ -0,0 +1,202 @@ +#!/usr/bin/env python3 +# SPDX-License-Identifier: MIT +# Copyright 2026 Timothy Place and the SampleRateTap contributors +"""Report on an alsa_bridge --csv run (docs/HARDWARE_TESTING.md, Setup 1). + + alsa_bridge_report.py RUN.csv [--skip SECONDS] [--plot OUT.png] + alsa_bridge_report.py --self-test + +The bridge logs, once per second, the converter's status() beside each +device's cumulative frame count and CLOCK_MONOTONIC_RAW (and, where the +driver gives them, each device's last hardware pointer update with its own +timestamp). This script answers the bench's questions from that record: + +- What are the two crystals' rates? A least-squares line through each + device's frames against time gives its rate in frames per second, from the + threads' counts and, where present, from the hardware timestamps, which + carry no scheduling jitter. Their ratio is the true clock offset, + (rate_in / rate_out - 1) * 1e6 ppm, the quantity the servo estimates. +- Does the servo agree? The mean of its ppm over the locked rows, against + that measured offset. +- How quiet is it? The ppm "wobble" (standard deviation and peak to peak + of the per-second estimate while locked) and the FIFO's "breathing" (the + same of its smoothed fill). +- Did anything break? The final underrun, overrun, resync and ALSA xrun + counts, which a soak must hold at zero. + +Standard library only; --plot needs matplotlib. --self-test checks the +arithmetic against a synthetic run with known rates and noise. +""" +import argparse +import csv +import math +import random +import statistics +import sys +import tempfile + + +def fit_rate(t_s: list[float], frames: list[float]) -> tuple[float, float]: + """Least-squares slope (frames per second) and the residuals' RMS.""" + n = len(t_s) + if n < 2: + return math.nan, math.nan + mt = sum(t_s) / n + mf = sum(frames) / n + sxx = sum((t - mt) ** 2 for t in t_s) + if sxx == 0.0: + return math.nan, math.nan + slope = sum((t - mt) * (f - mf) for t, f in zip(t_s, frames)) / sxx + resid = [f - (mf + slope * (t - mt)) for t, f in zip(t_s, frames)] + return slope, math.sqrt(sum(r * r for r in resid) / n) + + +def load(path: str) -> list[dict[str, str]]: + with open(path, newline="") as f: + return list(csv.DictReader(f)) + + +def spread(values: list[float]) -> tuple[float, float, float]: + """Mean, standard deviation and peak to peak (NaN when empty).""" + if not values: + return math.nan, math.nan, math.nan + sd = statistics.pstdev(values) if len(values) > 1 else 0.0 + return statistics.fmean(values), sd, max(values) - min(values) + + +def analyse(rows: list[dict[str, str]], skip_s: float) -> dict: + rows = [r for r in rows if float(r["time_s"]) > skip_s] + if len(rows) < 2: + raise SystemExit("not enough rows after --skip") + out: dict = {"rows": len(rows), "seconds": float(rows[-1]["time_s"]) - float(rows[0]["time_s"])} + + t = [int(r["mono_raw_ns"]) * 1e-9 for r in rows] + for dev in ("in", "out"): + out[f"{dev}_rate"], out[f"{dev}_rms"] = fit_rate(t, [float(r[f"{dev}_frames"]) for r in rows]) + hw = [r for r in rows if r.get(f"{dev}_hw_ns")] + if len(hw) >= 2: + out[f"{dev}_hw_rate"], out[f"{dev}_hw_rms"] = fit_rate( + [int(r[f"{dev}_hw_ns"]) * 1e-9 for r in hw], [float(r[f"{dev}_hw_frames"]) for r in hw]) + else: + out[f"{dev}_hw_rate"] = out[f"{dev}_hw_rms"] = math.nan + out["ppm_measured"] = (out["in_rate"] / out["out_rate"] - 1.0) * 1e6 + out["ppm_measured_hw"] = (out["in_hw_rate"] / out["out_hw_rate"] - 1.0) * 1e6 + + locked = [r for r in rows if r["state"] == "Locked"] + out["locked_rows"] = len(locked) + out["ppm_mean"], out["ppm_sd"], out["ppm_pp"] = spread([float(r["ppm"]) for r in locked]) + out["fill_mean"], out["fill_sd"], out["fill_pp"] = spread([float(r["fill"]) for r in locked]) + + last = rows[-1] + for k in ("underruns", "overruns", "resyncs", "in_xruns", "out_xruns", "in_errors", "out_errors"): + out[k] = int(last[k]) + return out + + +def report(a: dict) -> str: + def ppm(v: float) -> str: + return "n/a" if math.isnan(v) else f"{v:+.3f} ppm" + + lines = [ + f"{a['rows']} rows over {a['seconds']:.0f} s ({a['locked_rows']} locked)", + f"input {a['in_rate']:.4f} frames/s (thread counts, residual rms {a['in_rms']:.1f} frames)", + f"output {a['out_rate']:.4f} frames/s (thread counts, residual rms {a['out_rms']:.1f} frames)", + f"measured offset: {ppm(a['ppm_measured'])} (thread counts)", + f"measured offset, hw: {ppm(a['ppm_measured_hw'])} (hardware timestamps)", + f"servo, mean while locked: {ppm(a['ppm_mean'])} " + f"(servo minus measured {ppm(a['ppm_mean'] - a['ppm_measured'])})", + f"ppm wobble while locked: sd {a['ppm_sd']:.3f}, peak to peak {a['ppm_pp']:.3f}", + f"fill breathing: mean {a['fill_mean']:.2f}, sd {a['fill_sd']:.3f}, " + f"peak to peak {a['fill_pp']:.3f} frames", + f"underruns {a['underruns']}, overruns {a['overruns']}, resyncs {a['resyncs']}, " + f"xruns in {a['in_xruns']} out {a['out_xruns']}, other recoveries in {a['in_errors']} " + f"out {a['out_errors']}", + ] + return "\n".join(lines) + + +def plot(rows: list[dict[str, str]], a: dict, path: str) -> None: + import matplotlib # noqa: PLC0415 (optional dependency) + matplotlib.use("Agg") + import matplotlib.pyplot as plt # noqa: PLC0415 + + t = [float(r["time_s"]) for r in rows] + fig, (ax1, ax2) = plt.subplots(2, 1, sharex=True, figsize=(9, 6)) + ax1.plot(t, [float(r["ppm"]) for r in rows], lw=0.8, label="servo ppm") + ax1.axhline(a["ppm_measured"], color="k", ls="--", lw=0.8, label="measured (frame counts)") + ax1.set_ylabel("ppm") + ax1.legend() + ax2.plot(t, [float(r["fill"]) for r in rows], lw=0.8) + ax2.set_ylabel("FIFO fill (frames)") + ax2.set_xlabel("time (s)") + fig.tight_layout() + fig.savefig(path, dpi=120) + + +def self_test() -> int: + """A synthetic hour: input 80 ppm fast against a 48 kHz output, frame + counts sampled with up to a period of jitter, hardware timestamps exact + to 2 us, a servo estimate that wobbles 0.5 ppm round the truth.""" + rng = random.Random(1) + true_ppm, fs = 80.0, 48000.0 + rate_in, rate_out = fs * (1 + true_ppm * 1e-6), fs + fields = ["time_s", "state", "ppm", "fill", "underruns", "overruns", "resyncs", "mono_raw_ns", + "in_frames", "out_frames", "in_xruns", "out_xruns", "in_errors", "out_errors", + "in_hw_frames", "in_hw_ns", "out_hw_frames", "out_hw_ns"] + with tempfile.NamedTemporaryFile("w", suffix=".csv", delete=False, newline="") as f: + w = csv.DictWriter(f, fieldnames=fields) + w.writeheader() + t0 = 1_000_000_000_000 + for s in range(1, 3601): + ns = t0 + s * 1_000_000_000 + hw_ns_in = ns - rng.randrange(0, 2_000_000) + hw_ns_out = ns - rng.randrange(0, 2_000_000) + w.writerow({ + "time_s": s, "state": "Locked" if s > 30 else "Acquiring", + "ppm": f"{true_ppm + rng.gauss(0, 0.5):.3f}", "fill": f"{96 + rng.gauss(0, 2):.2f}", + "underruns": 0, "overruns": 0, "resyncs": 0, "mono_raw_ns": ns, + "in_frames": int(rate_in * (ns - t0) * 1e-9) - rng.randrange(0, 128), + "out_frames": int(rate_out * (ns - t0) * 1e-9) - rng.randrange(0, 128), + "in_xruns": 0, "out_xruns": 0, "in_errors": 0, "out_errors": 0, + "in_hw_frames": round(rate_in * (hw_ns_in - t0) * 1e-9), "in_hw_ns": hw_ns_in, + "out_hw_frames": round(rate_out * (hw_ns_out - t0) * 1e-9), "out_hw_ns": hw_ns_out, + }) + path = f.name + a = analyse(load(path), skip_s=60) + print(report(a)) + checks = [ + ("thread-count offset within 0.05 ppm", abs(a["ppm_measured"] - true_ppm) < 0.05), + ("hardware offset within 0.001 ppm", abs(a["ppm_measured_hw"] - true_ppm) < 0.001), + ("servo mean within 0.05 ppm", abs(a["ppm_mean"] - true_ppm) < 0.05), + ("wobble sd near 0.5", abs(a["ppm_sd"] - 0.5) < 0.05), + ("breathing sd near 2", abs(a["fill_sd"] - 2.0) < 0.2), + ("only locked rows count", a["locked_rows"] == 3600 - 60), + ] + failed = [name for name, ok in checks if not ok] + for name, ok in checks: + print(f"{'ok ' if ok else 'FAIL'} {name}") + return 1 if failed else 0 + + +def main() -> int: + ap = argparse.ArgumentParser(description=__doc__.split("\n")[0]) + ap.add_argument("csv", nargs="?", help="the bridge's --csv output") + ap.add_argument("--skip", type=float, default=60.0, + help="seconds to leave out at the start (acquisition; default 60)") + ap.add_argument("--plot", help="write the ppm and fill traces to this image (needs matplotlib)") + ap.add_argument("--self-test", action="store_true", help="check the arithmetic on a synthetic run") + args = ap.parse_args() + if args.self_test: + return self_test() + if not args.csv: + ap.error("a CSV path is required (or --self-test)") + rows = load(args.csv) + a = analyse(rows, args.skip) + print(report(a)) + if args.plot: + plot([r for r in rows if float(r["time_s"]) > args.skip], a, args.plot) + return 0 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/book/src/part5/hardware.md b/book/src/part5/hardware.md index 95166a4..3c2ac97 100644 --- a/book/src/part5/hardware.md +++ b/book/src/part5/hardware.md @@ -77,7 +77,7 @@ each one is the library's documented rules applied under witness. ## The ALSA bridge: two blocking threads, on purpose -The bridge is ~370 lines and structurally almost insolently simple: open a +The bridge is ~590 lines and structurally almost insolently simple: open a capture device and a playback device, start two threads, and let each thread block on its device. @@ -156,8 +156,16 @@ three scaling axes.) **The telemetry switches are the experiment design.** Three flags turn the bridge from a demo into an instrument: -- `--csv ` appends the once-per-second `status()` snapshot — state, - ppm, smoothed fill, underrun/overrun/resync counters — as a CSV row. +- `--csv ` writes the once-per-second `status()` snapshot (state, + ppm, smoothed fill, underrun/overrun/resync counters) as a CSV row. Beside + it go the instruments that check the servo instead of trusting it: + `CLOCK_MONOTONIC_RAW`, each device's cumulative frame count, and its ALSA + xruns. Where the driver provides it, the row also carries each device's + last hardware pointer update with its own timestamp. A least-squares line + through each device's frames against time is that crystal's rate, and the + ratio of the two is the offset the servo is supposed to be estimating. + `examples/alsa_bridge_report.py` does that regression and reports the + servo's agreement with it, the ppm wobble and the fill's breathing. This is the soak's evidence: the ppm trace over hours *is* the thermal- drift measurement, and the counters' final values *are* the zero-discontinuity claim. Point a hair dryer at one dongle and the trace @@ -181,6 +189,14 @@ bridge from a demo into an instrument: measurement: a 997 Hz tone through two real crystals into the AES17 notebook. +Two refusals keep the instrument honest. The bridge opens `hw:` devices +only, and turns `default` or `plughw:` away before touching the hardware: a +plugin device may resample (on a Pi, `default` is PipeWire), and a bridge +measuring PipeWire's converter would report that converter's clock with a +straight face. And `--rt`, which runs both audio threads `SCHED_FIFO` with +memory locked, fails outright if the system refuses either, rather than +quietly measuring without it. + ## `pico2_cyccnt`: buying cycles with instructions Part II built a performance ratchet on QEMU instruction counts: @@ -397,8 +413,9 @@ the ledger as it stands: the real `%core@48k` figures, the hour-scale zero-discontinuity claim, and the thermal-drift trace are all, today, well-instrumented empty columns. -- **Not yet written:** the small script that plots a `--csv` ppm trace and - runs the notebook analysis over a `--dump` capture, and both Setup 3 +- **Not yet written:** the script that runs the notebook analysis over a + `--dump` capture (the `--csv` report, `alsa_bridge_report.py`, shipped + with the roadmap's A11), and both Setup 3 programs (UDP sender, receiver-with-ASRC — the plan is to reuse the bridge's output half). @@ -418,9 +435,12 @@ cmake -B build -DTAP_SR_BUILD_EXAMPLES=ON && cmake --build build -j # Setup 1 (Linux + two audio devices; tap_sr_async_alsa_bridge builds when ALSA # is found). Real clocks, synthetic tone, telemetry + capture: ./build/async/examples/tap_sr_async_alsa_bridge --in hw:1,0 --out hw:2,0 \ - --tone 997 --csv trace.csv --dump post_asrc.f32 --seconds 3600 -# Then: ppm column of trace.csv is the thermal-drift instrument; analyze -# post_asrc.f32 with the AES17 machinery in notebooks/asrc_comparison.ipynb. + --rt --tone 997 --csv trace.csv --dump post_asrc.f32 --seconds 3600 +# Then: the crystals' measured offset against the servo, the wobble and the +# breathing (--self-test checks the arithmetic without hardware): +python3 async/examples/alsa_bridge_report.py trace.csv --plot trace.png +# and analyze post_asrc.f32 with the AES17 machinery in +# notebooks/asrc_comparison.ipynb. # Setup 2 firmware (standalone builds; arm-none-eabi-gcc + network for # the Pico SDK fetch): diff --git a/docs/ROADMAP.md b/docs/ROADMAP.md index 39c73c9..762f0e4 100644 --- a/docs/ROADMAP.md +++ b/docs/ROADMAP.md @@ -130,7 +130,7 @@ gated on shipping. `docs/AUDIT_2026-10_PLAN.md` still says "execution in progress"; the comparison records' competitor pins are frozen by policy and each `COMPARISON.md` should say so with the date. -- **A11. Harness prerequisites for Block B** (written now, run then): the ALSA bridge +- **A11. Harness prerequisites for Block B** (written now, run then). *In three PRs. A11a landed 2026-10-15: the ALSA bridge's counters, xruns, `hw:`-only refusal, `--rt` and hardware timestamps, `examples/alsa_bridge_report.py` (the regression slope, wobble and breathing; self-tested), and `libasound2-dev` on the Linux legs and in the tidy gate. A11b is the `pico2_cyccnt` cases and A11c the UAC2 firmware.* the ALSA bridge gains per-device cumulative frame counters sampled with `clock_gettime` in the CSV, separate ALSA xrun counters, a refusal of non-`hw:` devices (the `default` device on a Pi routes through PipeWire and its own resampler), an `--rt` flag (`SCHED_FIFO`,