diff --git a/fedac/native/scripts/latency.mjs b/fedac/native/scripts/latency.mjs new file mode 100755 index 000000000..e0d0618f6 --- /dev/null +++ b/fedac/native/scripts/latency.mjs @@ -0,0 +1,224 @@ +#!/usr/bin/env node +// latency.mjs — ac-native audio jitter / latency floor measurement +// +// Drives the AC_LATENCY_BENCH=1 mode added in audio.c. The audio thread +// emits one "[ac-latency] ..." line per ~1024 periods (≈1s of audio +// at the 1ms HDA period, ≈20s at the 20ms SOF period). This script +// parses those lines and reports the empirical audio-side latency +// floor — the period interval the kernel actually delivers, plus the +// jitter on it. +// +// What the floor means: +// period_us = 1000 / sample_rate * period_frames (ALSA configured) +// min = best observed period delivery time (idle floor) +// p50/mean = typical period delivery time (steady-state) +// p99/max = worst-case delivery time (jitter ceiling) +// over_period = count of periods that took >1.5× (audible drift) +// xruns = total ALSA underruns since boot (audible glitches) +// +// Total key-to-DAC latency, per the latency paper: +// key→evdev (~100µs) + dispatch (~100µs) + ALSA period (this number) +// + DMA turnaround (codec-specific, ~1ms HDA / ~80ms SOF firmware) +// +// Usage: +// # 1. Spawn a built ac-native binary directly (e.g. on a dev Linux +// # box with ALSA, or under QEMU). Best for A/B comparing C +// # changes against a baseline: +// node latency.mjs --bin /path/to/ac-native [--seconds 30] +// +// # 2. Tail journalctl on a running AC OS device. AC_LATENCY_BENCH=1 +// # must be set in the kernel cmdline or unit env. Pipe the +// # matching log stream into stdin: +// journalctl -f -o cat -u ac-native | node latency.mjs --tail +// ssh ac-os-device 'journalctl -f -o cat' | node latency.mjs --tail +// +// # 3. Read a static log file (offline analysis): +// node latency.mjs --file /tmp/ac-native.log +// +// Output: +// Streaming per-report stats as they arrive, plus a final summary +// when the stream ends or --seconds elapses. + +import { spawn } from "node:child_process"; +import { createReadStream } from "node:fs"; +import { createInterface } from "node:readline"; + +const args = process.argv.slice(2); +const opt = (name, fallback = null) => { + const i = args.indexOf(name); + return i >= 0 ? args[i + 1] : fallback; +}; +const has = (name) => args.includes(name); + +if (has("--help") || has("-h")) { + process.stdout.write( + `latency.mjs — ac-native audio jitter / latency floor measurement\n\n` + + ` --bin spawn ac-native binary, capture stderr\n` + + ` --tail parse [ac-latency] lines from stdin\n` + + ` --file parse [ac-latency] lines from a log file\n` + + ` --seconds auto-stop spawn mode after n seconds (default: 30)\n` + + ` --json emit per-report records as JSON to stdout\n` + + ` --help show this message\n` + ); + process.exit(0); +} + +const mode = has("--tail") ? "tail" : opt("--file") ? "file" : opt("--bin") ? "spawn" : null; +if (!mode) { + process.stderr.write("latency.mjs: choose --bin, --tail, or --file (see --help)\n"); + process.exit(2); +} + +const seconds = parseInt(opt("--seconds", "30"), 10); +const jsonOut = has("--json"); + +// Rolling aggregation across all reports in this run. +const all = { + reports: 0, + period_us: null, + min: Infinity, + max: 0, + meanSum: 0, // sum of per-report means + p50Sum: 0, + p99Sum: 0, + overPeriodTotal: 0, + xrunsLast: 0, + xrunsFirst: null, + samplesTotal: 0, +}; + +// One-line ac-latency report parser. +const RE = /^\[ac-latency\]\s+period_us=(\d+)\s+n=(\d+)\s+min=(\d+)\s+p50=(\d+)\s+mean=(\d+)\s+p99=(\d+)\s+max=(\d+)\s+over_period=(\d+)\s+xruns=(\d+)/; + +function parseLine(line) { + const m = RE.exec(line); + if (!m) return null; + return { + period_us: +m[1], + n: +m[2], + min: +m[3], + p50: +m[4], + mean: +m[5], + p99: +m[6], + max: +m[7], + over_period: +m[8], + xruns: +m[9], + }; +} + +function fmt(us) { + if (us < 1000) return `${us}µs`; + return `${(us / 1000).toFixed(2)}ms`; +} + +function onReport(r) { + all.reports++; + if (all.period_us == null) all.period_us = r.period_us; + if (r.min < all.min) all.min = r.min; + if (r.max > all.max) all.max = r.max; + all.meanSum += r.mean; + all.p50Sum += r.p50; + all.p99Sum += r.p99; + all.overPeriodTotal += r.over_period; + if (all.xrunsFirst == null) all.xrunsFirst = r.xruns; + all.xrunsLast = r.xruns; + all.samplesTotal += r.n; + + if (jsonOut) { + process.stdout.write(JSON.stringify(r) + "\n"); + return; + } + process.stdout.write( + `[#${String(all.reports).padStart(3)}] ` + + `period=${fmt(r.period_us)} ` + + `min=${fmt(r.min)} ` + + `p50=${fmt(r.p50)} ` + + `mean=${fmt(r.mean)} ` + + `p99=${fmt(r.p99)} ` + + `max=${fmt(r.max)} ` + + `over=${r.over_period}/${r.n} ` + + `xruns=${r.xruns}\n` + ); +} + +function summarize() { + if (all.reports === 0) { + process.stderr.write( + "latency.mjs: no [ac-latency] lines seen — was AC_LATENCY_BENCH=1 set?\n" + ); + process.exit(1); + } + const meanAvg = Math.round(all.meanSum / all.reports); + const p50Avg = Math.round(all.p50Sum / all.reports); + const p99Avg = Math.round(all.p99Sum / all.reports); + const xrunsDelta = all.xrunsLast - (all.xrunsFirst ?? 0); + const jitterMin = all.min - all.period_us; + const jitterP50 = p50Avg - all.period_us; + const jitterP99 = p99Avg - all.period_us; + const jitterMax = all.max - all.period_us; + + process.stdout.write( + "\n" + + "═══ summary ═══════════════════════════════════════════════════════\n" + + `reports : ${all.reports} (${all.samplesTotal} samples total)\n` + + `configured period: ${fmt(all.period_us)}\n` + + `delivered min : ${fmt(all.min)} (jitter ${jitterMin >= 0 ? "+" : "-"}${fmt(Math.abs(jitterMin))})\n` + + `delivered p50 : ${fmt(p50Avg)} (jitter ${jitterP50 >= 0 ? "+" : "-"}${fmt(Math.abs(jitterP50))})\n` + + `delivered mean : ${fmt(meanAvg)}\n` + + `delivered p99 : ${fmt(p99Avg)} (jitter ${jitterP99 >= 0 ? "+" : "-"}${fmt(Math.abs(jitterP99))})\n` + + `delivered max : ${fmt(all.max)} (jitter ${jitterMax >= 0 ? "+" : "-"}${fmt(Math.abs(jitterMax))})\n` + + `over-period : ${all.overPeriodTotal} periods >1.5× expected\n` + + `xruns delta : ${xrunsDelta} (during this run)\n` + + "\n" + + "estimated audio-side floor (period + DMA turnaround):\n" + + ` HDA-direct : ${fmt(all.period_us + 1000)} (1ms codec turnaround)\n` + + ` SOF firmware : ${fmt(all.period_us + 80000)} (80ms DAPM ceiling)\n` + + "\n" + + "key-to-DAC ≈ ~200µs (kbd+IRQ+dispatch) + audio-side floor + jitter ceiling\n" + + "═══════════════════════════════════════════════════════════════════\n" + ); +} + +async function readStream(stream) { + const rl = createInterface({ input: stream, crlfDelay: Infinity }); + for await (const raw of rl) { + // Strip ANSI + journalctl prefixes, find the [ac-latency] tag. + const idx = raw.indexOf("[ac-latency]"); + if (idx < 0) continue; + const r = parseLine(raw.slice(idx)); + if (r) onReport(r); + } +} + +async function runSpawn(binPath) { + const env = { ...process.env, AC_LATENCY_BENCH: "1" }; + const child = spawn(binPath, [], { env, stdio: ["ignore", "inherit", "pipe"] }); + let timer = null; + if (seconds > 0) { + timer = setTimeout(() => { + process.stderr.write(`latency.mjs: ${seconds}s elapsed — stopping ac-native\n`); + child.kill("SIGTERM"); + }, seconds * 1000); + } + child.on("exit", () => clearTimeout(timer)); + await readStream(child.stderr); +} + +(async () => { + process.on("SIGINT", () => { + summarize(); + process.exit(0); + }); + + if (mode === "spawn") { + await runSpawn(opt("--bin")); + } else if (mode === "file") { + await readStream(createReadStream(opt("--file"))); + } else { + await readStream(process.stdin); + } + summarize(); +})().catch((err) => { + process.stderr.write(`latency.mjs: ${err.message}\n`); + process.exit(1); +}); diff --git a/fedac/native/src/audio.c b/fedac/native/src/audio.c index 11469d292..d2e4f9a11 100644 --- a/fedac/native/src/audio.c +++ b/fedac/native/src/audio.c @@ -1,12 +1,15 @@ // audio.c — ALSA sound engine for ac-native // Dedicated audio thread with multi-voice synthesis, envelopes, and effects. +#define _GNU_SOURCE // pthread_setaffinity_np, CPU_SET, cpu_set_t + #include "audio.h" #include #include #include #include #include +#include #include #include #include @@ -19,6 +22,12 @@ extern void ac_log(const char *fmt, ...); // Forward declarations static int read_system_volume_card(int card); +// qsort comparator for AC_LATENCY_BENCH percentile computation. +static int bench_cmp_long(const void *a, const void *b) { + long la = *(const long *)a, lb = *(const long *)b; + return (la > lb) - (la < lb); +} + // ============================================================ // Note frequency table (octave 0 base frequencies) // ============================================================ @@ -1331,6 +1340,51 @@ static void *audio_thread_fn(void *arg) { if (pthread_setschedparam(pthread_self(), SCHED_FIFO, &sp) != 0) fprintf(stderr, "[audio] Warning: couldn't set RT priority\n"); + /* Pin the audio thread to the last online CPU. CPU 0 typically + * services timer/network/USB IRQs; isolating audio on a separate + * core tightens the jitter ceiling without affecting median. + * Disable with AC_AUDIO_NO_PIN=1 if it conflicts with isolcpus. */ + if (!getenv("AC_AUDIO_NO_PIN")) { + long ncpu = sysconf(_SC_NPROCESSORS_ONLN); + if (ncpu > 1) { + int target = (int)(ncpu - 1); + cpu_set_t cs; + CPU_ZERO(&cs); + CPU_SET(target, &cs); + if (pthread_setaffinity_np(pthread_self(), sizeof(cs), &cs) != 0) + fprintf(stderr, "[audio] Warning: couldn't pin audio thread to CPU %d\n", target); + else + fprintf(stderr, "[audio] Pinned to CPU %d (of %ld online)\n", target, ncpu); + } + } + + /* Optional jitter benchmark: AC_LATENCY_BENCH=1 makes the audio + * thread record per-period wall-clock intervals and emit a + * single-line stats summary every PERIODS_PER_REPORT iterations. + * Output format (one line per report, parseable by latency.mjs): + * [ac-latency] period_us= n= min= p50= + * mean= p99= max= over_period_us= xruns= + */ + const int latency_bench = getenv("AC_LATENCY_BENCH") && + getenv("AC_LATENCY_BENCH")[0] == '1'; + const int PERIODS_PER_REPORT = 1024; + long expected_period_us = (long)(((double)period_frames / (double)rate) * 1e6); + /* Keep a small ring of recent intervals so we can compute p50/p99 + * without storing every sample for the lifetime of the program. */ + long *bench_us = NULL; + int bench_count = 0; + long bench_min = LONG_MAX, bench_max = 0, bench_sum = 0; + long bench_over_period = 0; // periods that took > 1.5x expected + struct timespec bench_prev_ts = {0}; + if (latency_bench) { + bench_us = (long *)calloc(PERIODS_PER_REPORT, sizeof(long)); + /* bench_prev_ts left at {0,0} — set on first iteration below + * so the first delta is skipped (it would include startup + * prefill, not a real period interval). */ + fprintf(stderr, "[ac-latency] benchmark enabled — period_us=%ld report=%d periods\n", + expected_period_us, PERIODS_PER_REPORT); + } + while (audio->running) { memset(buffer, 0, sizeof(buffer)); @@ -1865,7 +1919,12 @@ static void *audio_thread_fn(void *arg) { const void *wptr = buffer32 ? (const void *)(buffer32 + offset * AUDIO_CHANNELS) : (const void *)(buffer + offset * AUDIO_CHANNELS); - int frames = snd_pcm_writei(pcm, wptr, remaining); + /* mmap_writei skips a buffer copy versus writei; falls + * through to writei when access wasn't negotiated as + * MMAP_INTERLEAVED. */ + int frames = audio->use_mmap + ? snd_pcm_mmap_writei(pcm, wptr, remaining) + : snd_pcm_writei(pcm, wptr, remaining); if (frames == -EAGAIN) continue; if (frames < 0) { int rec = snd_pcm_recover(pcm, frames, 1); @@ -1892,8 +1951,50 @@ static void *audio_thread_fn(void *arg) { remaining -= frames; offset += frames; } + + /* Per-period jitter measurement (AC_LATENCY_BENCH=1). + * Time between successive writei completions = actual delivered + * period. Compare to expected to expose audio-thread scheduling + * jitter — the empirical floor for audio-side latency. */ + if (latency_bench && bench_us) { + struct timespec now_ts; + clock_gettime(CLOCK_MONOTONIC, &now_ts); + if (bench_prev_ts.tv_sec == 0 && bench_prev_ts.tv_nsec == 0) { + /* First iteration — establish the time origin and skip; + * the first delta would include startup prefill. */ + bench_prev_ts = now_ts; + } else { + long delta_us = (now_ts.tv_sec - bench_prev_ts.tv_sec) * 1000000L + + (now_ts.tv_nsec - bench_prev_ts.tv_nsec) / 1000L; + bench_prev_ts = now_ts; + bench_us[bench_count] = delta_us; + if (delta_us < bench_min) bench_min = delta_us; + if (delta_us > bench_max) bench_max = delta_us; + bench_sum += delta_us; + if (delta_us > expected_period_us * 3 / 2) bench_over_period++; + bench_count++; + } + if (bench_count >= PERIODS_PER_REPORT) { + /* qsort to compute p50/p99. n=1024 → ~10k comparisons, + * runs in tens of µs once per second of audio — well + * under one period budget on the RT audio thread. */ + int n = bench_count; + qsort(bench_us, n, sizeof(long), bench_cmp_long); + long p50 = bench_us[n / 2]; + long p99 = bench_us[(int)(n * 0.99)]; + long mean = bench_sum / n; + fprintf(stderr, + "[ac-latency] period_us=%ld n=%d min=%ld p50=%ld mean=%ld p99=%ld max=%ld over_period=%ld xruns=%lu\n", + expected_period_us, n, bench_min, p50, mean, + p99, bench_max, bench_over_period, xrun_count); + bench_count = 0; + bench_min = LONG_MAX; bench_max = 0; bench_sum = 0; + bench_over_period = 0; + } + } } + free(bench_us); free(buffer); free(buffer32); return NULL; @@ -2268,7 +2369,21 @@ ACAudio *audio_init(void) { snd_pcm_hw_params_t *params; snd_pcm_hw_params_alloca(¶ms); snd_pcm_hw_params_any(pcm, params); - snd_pcm_hw_params_set_access(pcm, params, SND_PCM_ACCESS_RW_INTERLEAVED); + /* Prefer MMAP_INTERLEAVED: snd_pcm_mmap_writei skips the kernel + * ring-buffer copy that snd_pcm_writei does, saving a fraction + * of a millisecond on HDA paths. Fall back to RW_INTERLEAVED if + * the hardware/driver doesn't expose mmap (rare on real PCMs; + * common on plughw with rate conversion). */ + audio->use_mmap = 0; + if (snd_pcm_hw_params_set_access(pcm, params, + SND_PCM_ACCESS_MMAP_INTERLEAVED) == 0) { + audio->use_mmap = 1; + fprintf(stderr, "[audio] Negotiated MMAP_INTERLEAVED access\n"); + } else { + snd_pcm_hw_params_any(pcm, params); + snd_pcm_hw_params_set_access(pcm, params, SND_PCM_ACCESS_RW_INTERLEAVED); + fprintf(stderr, "[audio] Negotiated RW_INTERLEAVED access (no mmap)\n"); + } /* SOF topology FE PCMs use S32_LE internally; the SSP1 BE DAI * (MAX98360A) runs S24_LE. Writing S16_LE to this pipeline * causes 48dB attenuation + quantization noise ("crunchy quiet"). @@ -2282,8 +2397,13 @@ ACAudio *audio_init(void) { audio->use_s32 = 1; fprintf(stderr, "[audio] Negotiated S32_LE format (SOF)\n"); } else { + /* Re-negotiate from scratch with S16_LE; preserve the access + * mode we picked above. */ snd_pcm_hw_params_any(pcm, params); - snd_pcm_hw_params_set_access(pcm, params, SND_PCM_ACCESS_RW_INTERLEAVED); + snd_pcm_hw_params_set_access(pcm, params, + audio->use_mmap + ? SND_PCM_ACCESS_MMAP_INTERLEAVED + : SND_PCM_ACCESS_RW_INTERLEAVED); snd_pcm_hw_params_set_format(pcm, params, SND_PCM_FORMAT_S16_LE); fprintf(stderr, "[audio] Negotiated S16_LE format%s\n", sof_active ? " (S32_LE rejected)" : " (non-SOF, forced)"); @@ -2357,6 +2477,7 @@ ACAudio *audio_init(void) { snd_pcm_close(pcm); err = snd_pcm_open(&pcm, "plughw:0,0", SND_PCM_STREAM_PLAYBACK, 0); if (err >= 0) { + audio->use_mmap = 0; // plughw rate-conv path: no mmap snd_pcm_hw_params_any(pcm, params); snd_pcm_hw_params_set_access(pcm, params, SND_PCM_ACCESS_RW_INTERLEAVED); snd_pcm_hw_params_set_format(pcm, params, SND_PCM_FORMAT_S16_LE); diff --git a/fedac/native/src/audio.h b/fedac/native/src/audio.h index d7e9493d0..71373d1c0 100644 --- a/fedac/native/src/audio.h +++ b/fedac/native/src/audio.h @@ -316,6 +316,7 @@ typedef struct { unsigned int actual_rate; // Negotiated ALSA sample rate (may differ from requested) unsigned int actual_period; // Negotiated ALSA period size in frames int use_s32; // 1 if PCM negotiated S32_LE (SOF boards), 0 for S16_LE + int use_mmap; // 1 if PCM negotiated MMAP_INTERLEAVED access, 0 for RW // TTS PCM buffer (resampled to output rate, mono → stereo in mix) float *tts_buf; // ring buffer of mono float samples at output rate