diff --git a/RemSound-mini-logs-2026-08-14-234223.zip b/RemSound-mini-logs-2026-08-14-234223.zip new file mode 100644 index 0000000..4256b2d Binary files /dev/null and b/RemSound-mini-logs-2026-08-14-234223.zip differ diff --git a/lab-classic-after.txt b/lab-classic-after.txt new file mode 100644 index 0000000..780adac --- /dev/null +++ b/lab-classic-after.txt @@ -0,0 +1,18 @@ +RemSound latency lab - measuring depth-target convergence with the shipped playout code. +Raise under test: 30ms -> 330ms. Expected growth at full depth-bias: ~3ms/s. + +--- T3 classic app path: WASAPI lane active, slider drives Mixed --- + session route after arrival: WasapiLane (slider writes to: Mixed) + settled at slider 30ms: buffered=70ms + t+10s buffered= 48ms + t+20s buffered= 66ms + t+30s buffered= 114ms + t+40s buffered= 125ms + t+50s buffered= 165ms + t+60s buffered= 194ms + RAISE via slider: 70ms -> 194ms in 60s = 2.07ms/s GROWS (slider works) + LOWER via slider: back to 30ms -> buffered=48ms after 3s + + +=== SUMMARY === + T3 classic app path: WASAPI lane active, slider drives Mixed: raise 2.07ms/s [GROWS (slider works)], lower -> 48ms diff --git a/lab-classic-before.txt b/lab-classic-before.txt new file mode 100644 index 0000000..4b6b8f8 --- /dev/null +++ b/lab-classic-before.txt @@ -0,0 +1,18 @@ +RemSound latency lab - measuring depth-target convergence with the shipped playout code. +Raise under test: 30ms -> 330ms. Expected growth at full depth-bias: ~3ms/s. + +--- T3 classic app path: WASAPI lane active, slider drives Mixed --- + session route after arrival: WasapiLane (slider writes to: Mixed) + settled at slider 30ms: buffered=39ms + t+10s buffered= 19ms + t+20s buffered= 39ms + t+30s buffered= 38ms + t+40s buffered= 29ms + t+50s buffered= 20ms + t+60s buffered= 30ms + RAISE via slider: 39ms -> 30ms in 60s = -0.15ms/s STALLED (the field bug) + LOWER via slider: back to 30ms -> buffered=1ms after 3s + + +=== SUMMARY === + T3 classic app path: WASAPI lane active, slider drives Mixed: raise -0.15ms/s [STALLED (the field bug)], lower -> 21ms diff --git a/lab-classic-err.txt b/lab-classic-err.txt new file mode 100644 index 0000000..e69de29 diff --git a/lab-classic-err2.txt b/lab-classic-err2.txt new file mode 100644 index 0000000..e69de29 diff --git a/lab-classic-fast.txt b/lab-classic-fast.txt new file mode 100644 index 0000000..4c96566 --- /dev/null +++ b/lab-classic-fast.txt @@ -0,0 +1,18 @@ +RemSound latency lab - measuring depth-target convergence with the shipped playout code. +Raise under test: 30ms -> 330ms. Expected growth at full depth-bias: ~3ms/s. + +--- T3 classic app path: WASAPI lane active, slider drives Mixed --- + session route after arrival: WasapiLane (slider writes to: Mixed) + settled at slider 30ms: buffered=49ms + t+10s buffered= 324ms + t+20s buffered= 335ms + t+30s buffered= 339ms + t+40s buffered= 301ms + t+50s buffered= 305ms + t+60s buffered= 306ms + RAISE via slider: 49ms -> 306ms in 60s = 4.28ms/s GROWS (slider works) + LOWER via slider: back to 30ms -> buffered=55ms after 3s + + +=== SUMMARY === + T3 classic app path: WASAPI lane active, slider drives Mixed: raise 4.28ms/s [GROWS (slider works)], lower -> 55ms diff --git a/lab-err3.txt b/lab-err3.txt new file mode 100644 index 0000000..e69de29 diff --git a/latency-lab-err.txt b/latency-lab-err.txt new file mode 100644 index 0000000..e69de29 diff --git a/latency-lab-out.txt b/latency-lab-out.txt new file mode 100644 index 0000000..7fbcfb0 --- /dev/null +++ b/latency-lab-out.txt @@ -0,0 +1,113 @@ +RemSound latency lab - measuring depth-target convergence with the shipped playout code. +Raise under test: 30ms -> 330ms. Expected growth at full depth-bias: ~3ms/s. + +--- T1 clean: write 10ms/10ms, read 10ms/10ms --- + settled at target 30ms: buffered=38ms ratio=1.001000 updates=1 + t+ 5s buffered= 10ms ratio=1.000101 updates=2 + t+10s buffered= 34ms ratio=1.000101 updates=2 + t+15s buffered= 49ms ratio=1.000070 updates=3 + t+20s buffered= 74ms ratio=1.000070 updates=3 + t+25s buffered= 78ms ratio=1.000049 updates=4 + t+30s buffered= 103ms ratio=1.000049 updates=4 + t+35s buffered= 98ms ratio=1.000635 updates=5 + t+40s buffered= 140ms ratio=1.000635 updates=5 + t+45s buffered= 132ms ratio=0.999845 updates=6 + t+50s buffered= 148ms ratio=0.999845 updates=6 + t+55s buffered= 184ms ratio=0.999892 updates=7 + t+60s buffered= 200ms ratio=0.999892 updates=7 + RAISE result: 38ms -> 200ms in 60s = 2.70ms/s GROWS (mechanism working) + LOWER result: back to target 30ms -> buffered=69ms after 3s + +--- T1 opus-frame: write 20ms/20ms, read 10ms/10ms --- + settled at target 30ms: buffered=76ms ratio=0.998000 updates=1 + t+ 5s buffered= 58ms ratio=0.999200 updates=2 + t+10s buffered= 97ms ratio=0.999200 updates=2 + t+15s buffered= 126ms ratio=0.998841 updates=3 + t+20s buffered= 127ms ratio=0.998841 updates=3 + t+25s buffered= 158ms ratio=1.000088 updates=4 + t+30s buffered= 153ms ratio=1.000088 updates=4 + t+35s buffered= 177ms ratio=1.000062 updates=5 + t+40s buffered= 202ms ratio=1.000062 updates=5 + t+45s buffered= 207ms ratio=0.999144 updates=6 + t+50s buffered= 237ms ratio=0.999144 updates=6 + t+55s buffered= 266ms ratio=1.000001 updates=7 + t+60s buffered= 271ms ratio=1.000001 updates=7 + RAISE result: 76ms -> 271ms in 60s = 3.25ms/s GROWS (mechanism working) + LOWER result: back to target 30ms -> buffered=59ms after 3s + +--- T1 gulpy device: write 20ms/20ms, read 21ms + 42ms gulp each ~1s --- + settled at target 30ms: buffered=43ms ratio=1.000400 updates=1 + t+ 5s buffered= 41ms ratio=0.999771 updates=2 + t+10s buffered= 59ms ratio=0.999771 updates=2 + t+15s buffered= 53ms ratio=1.000529 updates=3 + t+20s buffered= 85ms ratio=1.000529 updates=3 + t+25s buffered= 97ms ratio=1.000460 updates=4 + t+30s buffered= 130ms ratio=1.000460 updates=4 + t+35s buffered= 142ms ratio=0.999214 updates=5 + t+40s buffered= 140ms ratio=0.999214 updates=5 + t+45s buffered= 158ms ratio=1.000737 updates=6 + t+50s buffered= 189ms ratio=1.000737 updates=6 + t+55s buffered= 180ms ratio=0.999408 updates=7 + t+60s buffered= 238ms ratio=0.999408 updates=7 + RAISE result: 43ms -> 238ms in 60s = 3.25ms/s GROWS (mechanism working) + LOWER result: back to target 30ms -> buffered=59ms after 3s + +--- T1 jittery net: write 20ms +/-15ms, read 10ms/10ms --- + settled at target 30ms: buffered=70ms ratio=1.002000 updates=1 + t+ 5s buffered= 50ms ratio=1.001100 updates=2 + t+10s buffered= 39ms ratio=1.001100 updates=2 + t+15s buffered= 79ms ratio=1.001370 updates=3 + t+20s buffered= 47ms ratio=1.001370 updates=3 + t+25s buffered= 85ms ratio=1.000359 updates=4 + t+30s buffered= 89ms ratio=1.000359 updates=4 + t+35s buffered= 82ms ratio=0.999952 updates=5 + t+40s buffered= 117ms ratio=0.999952 updates=5 + t+45s buffered= 132ms ratio=1.001166 updates=6 + t+50s buffered= 162ms ratio=1.001166 updates=6 + t+55s buffered= 162ms ratio=0.999619 updates=7 + t+60s buffered= 189ms ratio=0.999619 updates=7 + RAISE result: 70ms -> 189ms in 60s = 1.98ms/s SLOW (partially working) + LOWER result: back to target 30ms -> buffered=69ms after 3s + +--- T2 engine-Mixed clean: write 20ms/20ms, read 10ms/10ms --- + settled at target 30ms: buffered=74ms ratio=1.001001 updates=1 + t+ 5s buffered= 34ms ratio=1.000401 updates=2 + t+10s buffered= 21ms ratio=1.000401 updates=2 + t+15s buffered= 29ms ratio=1.000281 updates=3 + t+20s buffered= 29ms ratio=1.000281 updates=3 + t+25s buffered= 30ms ratio=0.999897 updates=4 + t+30s buffered= 34ms ratio=0.999897 updates=4 + t+35s buffered= 37ms ratio=0.999928 updates=5 + t+40s buffered= 38ms ratio=0.999928 updates=5 + t+45s buffered= 29ms ratio=0.999949 updates=6 + t+50s buffered= 30ms ratio=0.999949 updates=6 + t+55s buffered= 39ms ratio=1.000864 updates=7 + t+60s buffered= 9ms ratio=1.000864 updates=7 + RAISE result: 74ms -> 9ms in 60s = -1.08ms/s STALLED (the field bug) + LOWER result: back to target 30ms -> buffered=29ms after 3s + +--- T2 engine-Mixed gulpy: write 20ms/20ms, read 21ms + 42ms gulp --- + settled at target 30ms: buffered=59ms ratio=0.998399 updates=1 + t+ 5s buffered= 56ms ratio=0.999568 updates=2 + t+10s buffered= 28ms ratio=0.999568 updates=2 + t+15s buffered= 25ms ratio=0.999818 updates=3 + t+20s buffered= 50ms ratio=0.999818 updates=3 + t+25s buffered= 44ms ratio=0.999962 updates=4 + t+30s buffered= 48ms ratio=0.999962 updates=4 + t+35s buffered= 39ms ratio=0.999465 updates=5 + t+40s buffered= 20ms ratio=0.999465 updates=5 + t+45s buffered= 35ms ratio=0.999116 updates=6 + t+50s buffered= 50ms ratio=0.999116 updates=6 + t+55s buffered= 53ms ratio=0.999471 updates=7 + t+60s buffered= 50ms ratio=0.999471 updates=7 + RAISE result: 59ms -> 50ms in 60s = -0.15ms/s STALLED (the field bug) + LOWER result: back to target 30ms -> buffered=62ms after 3s + + +=== SUMMARY === + T1 clean: write 10ms/10ms, read 10ms/10ms: raise 2.70ms/s [GROWS (mechanism working)], lower -> 69ms + T1 opus-frame: write 20ms/20ms, read 10ms/10ms: raise 3.25ms/s [GROWS (mechanism working)], lower -> 59ms + T1 gulpy device: write 20ms/20ms, read 21ms + 42ms gulp each ~1s: raise 3.25ms/s [GROWS (mechanism working)], lower -> 59ms + T1 jittery net: write 20ms +/-15ms, read 10ms/10ms: raise 1.98ms/s [SLOW (partially working)], lower -> 69ms + T2 engine-Mixed clean: write 20ms/20ms, read 10ms/10ms: raise -1.08ms/s [STALLED (the field bug)], lower -> 29ms + T2 engine-Mixed gulpy: write 20ms/20ms, read 21ms + 42ms gulp: raise -0.15ms/s [STALLED (the field bug)], lower -> 62ms diff --git a/src/RemSound.App/CommandLine.cs b/src/RemSound.App/CommandLine.cs index ae0e512..6e7e4fa 100644 --- a/src/RemSound.App/CommandLine.cs +++ b/src/RemSound.App/CommandLine.cs @@ -88,6 +88,11 @@ internal static class CommandLine return WithConsole(() => SelfTest.Run(args)); case "--perftest": case "--perf-test": return WithConsole(() => RunPerfTest(args)); + case "--latency-lab": + // Diagnostic harness (2026-08-14 latency-slider field report): drives the real + // playout with realtime-paced sender/device shapes and MEASURES whether the + // buffered depth converges to a raised target. Developer tool, ~8 min runtime. + return WithConsole(() => LatencyLab.Run(args)); case "--diagnostics": case "--diag": return WithConsole(() => RunDiagnostics(ValueAfter(args, raw))); case "--log": diff --git a/src/RemSound.App/LatencyLab.cs b/src/RemSound.App/LatencyLab.cs new file mode 100644 index 0000000..c2644c6 --- /dev/null +++ b/src/RemSound.App/LatencyLab.cs @@ -0,0 +1,275 @@ +using System.Diagnostics; +using System.Net; +using RemSound.Core; +using RemSound.Receiver; + +namespace RemSound.App; + +/// +/// Measured latency-slider lab (--latency-lab), built for the 2026-08-14 field report: +/// raising the receive-latency slider audibly lengthens the delay on one machine and does nothing +/// on another — both plain WASAPI, both ordinary consumer outputs, auto-tune off. The mechanism +/// under test is SessionPlayout's depth-feedback resampler bias (raise = play ≤0.3% slow until the +/// ring grows to target ≈ +3ms of depth per second). This drives the REAL playout objects with a +/// realtime-paced producer (sender-shaped writes) and consumer (device-shaped reads), samples the +/// actual buffered depth once a second, and prints growth rates — so the diagnosis rests on +/// numbers from the shipped code, not on reasoning about it (the standing audio rule). +/// +/// Scenarios vary the two things that differ between working and stalled rigs: the write shape +/// (10ms PCM-ish vs 20ms Opus-frame-ish vs jittery arrival) and the read shape (clean 10ms +/// callbacks vs chunky 21ms callbacks with periodic double-gulps). Tier 2 re-runs the key shapes +/// through PlayoutEngine's Mixed-route Read — the exact single-slider plumbing a fresh install +/// uses — in case the stall lives above SessionPlayout. +/// +internal static class LatencyLab +{ + private const int SampleRate = 48000; + private const int BytesPerFrame = 2 * sizeof(float); // stereo float mix bus + private const int StartTargetMs = 30; + private const int RaisedTargetMs = 330; + private const int SettleSeconds = 15; // let the 10s drift window engage before judging + private const int MeasureSeconds = 60; // growth window: expect ~+3ms/s => ~+180ms + + public static int Run() => Run([]); + + public static int Run(string[] args) + { + Console.WriteLine("RemSound latency lab - measuring depth-target convergence with the shipped playout code."); + Console.WriteLine($"Raise under test: {StartTargetMs}ms -> {RaisedTargetMs}ms. Expected growth at full depth-bias: ~3ms/s."); + Console.WriteLine(); + + var results = new List(); + + // T3 — the FAITHFUL classic-mode app path (the field bug). Wires the engine exactly as the + // running app does: CompositeRenderBackend marks the WASAPI lane active (a ticked WASAPI + // output, no ASIO), which tags every session RenderRoute.WasapiLane; the single latency + // slider in every non-BothIndependent mode drives RenderRoute.Mixed (MainForm.MaxLatencyBox- + // Route). Run this alone with: --latency-lab classic + if (args.Any(a => string.Equals(a, "classic", StringComparison.OrdinalIgnoreCase))) + { + RunClassicAppPath(results, "T3 classic app path: WASAPI lane active, slider drives Mixed"); + Console.WriteLine(); + Console.WriteLine("=== SUMMARY ==="); + foreach (var line in results) Console.WriteLine(" " + line); + return 0; + } + RunScenario(results, "T1 clean: write 10ms/10ms, read 10ms/10ms", writeMs: 10, writeJitterMs: 0, readMs: 10, gulpEvery: 0, engineMixed: false); + RunScenario(results, "T1 opus-frame: write 20ms/20ms, read 10ms/10ms", writeMs: 20, writeJitterMs: 0, readMs: 10, gulpEvery: 0, engineMixed: false); + RunScenario(results, "T1 gulpy device: write 20ms/20ms, read 21ms + 42ms gulp each ~1s", writeMs: 20, writeJitterMs: 0, readMs: 21, gulpEvery: 48, engineMixed: false); + RunScenario(results, "T1 jittery net: write 20ms +/-15ms, read 10ms/10ms", writeMs: 20, writeJitterMs: 15, readMs: 10, gulpEvery: 0, engineMixed: false); + RunScenario(results, "T2 engine-Mixed clean: write 20ms/20ms, read 10ms/10ms", writeMs: 20, writeJitterMs: 0, readMs: 10, gulpEvery: 0, engineMixed: true); + RunScenario(results, "T2 engine-Mixed gulpy: write 20ms/20ms, read 21ms + 42ms gulp", writeMs: 20, writeJitterMs: 0, readMs: 21, gulpEvery: 48, engineMixed: true); + + Console.WriteLine(); + Console.WriteLine("=== SUMMARY ==="); + foreach (var line in results) Console.WriteLine(" " + line); + return 0; + } + + /// The classic-mode reproduction: engine wired exactly as the shipped app wires it for a + /// plain WASAPI setup, then the slider raised through the very call MainForm makes. Measures the + /// buffered depth the same way as the other scenarios. + private static void RunClassicAppPath(List results, string name) + { + Console.WriteLine($"--- {name} ---"); + var endpoint = new IPEndPoint(IPAddress.Loopback, 47831); + var engine = new PlayoutEngine(new ReceiverDiagnostics()); + + // 1. CompositeRenderBackend.SetOutputDevices: one WASAPI output ticked, no ASIO. + engine.SetLaneActive(RenderRoute.WasapiLane, true); + engine.SetLaneActive(RenderRoute.AsioLane, false); + // 2. The slider's startup value, applied the way MainForm applies it in classic mode. + engine.SetMaxLatencyMs(RenderRoute.Mixed, StartTargetMs); + // 3. A peer's stream arrives — ReconcileReplicasLocked tags it with the active lane. + var session = engine.GetOrCreateSession(endpoint, 1, capacityBytes: 4 * 1024 * 1024); + Console.WriteLine($" session route after arrival: {session.Route} (slider writes to: {RenderRoute.Mixed})"); + + const int WriteMs = 20, ReadMs = 10; + var stop = false; + var writeBlock = new byte[WriteMs * SampleRate / 1000 * BytesPerFrame]; + FillSine(writeBlock); + + var producer = new Thread(() => + { + var sw = Stopwatch.StartNew(); + var nextDueMs = 0.0; + while (!Volatile.Read(ref stop)) + { + session.Write(writeBlock); + session.NoteFramesQueued(engine.TargetLatencyMs); // AudioReceiver's queued-callback lambda + nextDueMs += WriteMs; + var sleep = nextDueMs - sw.Elapsed.TotalMilliseconds; + if (sleep > 0) Thread.Sleep((int)sleep); + } + }) { IsBackground = true, Name = "lab-producer" }; + + var readFrames = ReadMs * SampleRate / 1000; + var readBytes = new byte[readFrames * BytesPerFrame]; + var consumer = new Thread(() => + { + var sw = Stopwatch.StartNew(); + var nextDueMs = 0.0; + while (!Volatile.Read(ref stop)) + { + engine.Read(readBytes, 0, readBytes.Length); + nextDueMs += ReadMs; + var sleep = nextDueMs - sw.Elapsed.TotalMilliseconds; + if (sleep > 0) Thread.Sleep((int)sleep); + } + }) { IsBackground = true, Name = "lab-consumer" }; + + producer.Start(); + Thread.Sleep(120); + consumer.Start(); + Thread.Sleep(SettleSeconds * 1000); + var settled = session.BufferedMs; + Console.WriteLine($" settled at slider {StartTargetMs}ms: buffered={settled}ms"); + + // 4. The user drags the slider up mid-stream — MainForm's exact call. + engine.SetMaxLatencyMs(RenderRoute.Mixed, RaisedTargetMs); + for (var s = 0; s < MeasureSeconds; s++) + { + Thread.Sleep(1000); + if (s % 10 == 9) Console.WriteLine($" t+{s + 1,2}s buffered={session.BufferedMs,4}ms"); + } + var after = session.BufferedMs; + var growth = (after - settled) / (double)MeasureSeconds; + var verdict = growth >= 2.0 ? "GROWS (slider works)" : growth >= 0.5 ? "SLOW" : "STALLED (the field bug)"; + Console.WriteLine($" RAISE via slider: {settled}ms -> {after}ms in {MeasureSeconds}s = {growth:F2}ms/s {verdict}"); + + engine.SetMaxLatencyMs(RenderRoute.Mixed, StartTargetMs); + Thread.Sleep(3000); + Console.WriteLine($" LOWER via slider: back to {StartTargetMs}ms -> buffered={session.BufferedMs}ms after 3s"); + Console.WriteLine(); + results.Add($"{name}: raise {growth:F2}ms/s [{verdict}], lower -> {session.BufferedMs}ms"); + + stop = true; + producer.Join(2000); + consumer.Join(2000); + } + + private static void RunScenario(List results, string name, int writeMs, int writeJitterMs, int readMs, int gulpEvery, bool engineMixed) + { + Console.WriteLine($"--- {name} ---"); + var endpoint = new IPEndPoint(IPAddress.Loopback, 47831); + var diagnostics = new ReceiverDiagnostics(); + PlayoutEngine? engine = null; + SessionPlayout session; + var target = StartTargetMs; + if (engineMixed) + { + engine = new PlayoutEngine(diagnostics); + engine.SetMaxLatencyMs(StartTargetMs); + session = engine.GetOrCreateSession(endpoint, 1, capacityBytes: 4 * 1024 * 1024); + } + else + { + session = new SessionPlayout(endpoint, 1, capacityBytes: 4 * 1024 * 1024); + } + + var stop = false; + var writeBlock = new byte[writeMs * SampleRate / 1000 * BytesPerFrame]; + FillSine(writeBlock); // real signal, not silence - keeps every probe honest + var rng = new Random(12345); + + // Producer: sender-shaped realtime writes, exactly the AudioReceiver wiring + // (Write then NoteFramesQueued with the CURRENT target, like the queued-callback lambda). + var producer = new Thread(() => + { + var sw = Stopwatch.StartNew(); + var nextDueMs = 0.0; + while (!Volatile.Read(ref stop)) + { + session.Write(writeBlock); + session.NoteFramesQueued(engineMixed ? engine!.TargetLatencyMs : Volatile.Read(ref target)); + nextDueMs += writeMs; + var jitter = writeJitterMs > 0 ? rng.Next(-writeJitterMs, writeJitterMs + 1) : 0; + var sleep = nextDueMs + jitter - sw.Elapsed.TotalMilliseconds; + if (sleep > 0) Thread.Sleep((int)sleep); + } + }) { IsBackground = true, Name = "lab-producer" }; + + // Consumer: device-shaped reads. Clean cadence, or chunky with a periodic double-gulp. + var readBlockFrames = readMs * SampleRate / 1000; + var readFloats = new float[readBlockFrames * 2 * 2]; // x2 room for the gulp read + var readBytes = new byte[readFloats.Length * sizeof(float)]; + var consumer = new Thread(() => + { + var sw = Stopwatch.StartNew(); + var nextDueMs = 0.0; + var n = 0; + while (!Volatile.Read(ref stop)) + { + var gulp = gulpEvery > 0 && ++n % gulpEvery == 0; + var frames = gulp ? readBlockFrames * 2 : readBlockFrames; + if (engineMixed) + { + engine!.Read(readBytes, 0, frames * BytesPerFrame); + } + else + { + session.ReadFloats(readFloats.AsSpan(0, frames * 2), frames, Volatile.Read(ref target), Volatile.Read(ref target), smoothness: 3); + } + nextDueMs += gulp ? readMs * 2 : readMs; + var sleep = nextDueMs - sw.Elapsed.TotalMilliseconds; + if (sleep > 0) Thread.Sleep((int)sleep); + } + }) { IsBackground = true, Name = "lab-consumer" }; + + producer.Start(); + Thread.Sleep(120); // pre-fill past the arming threshold so playback starts + consumer.Start(); + + // Phase A: settle at the low target so the 10s drift-measurement window engages. + Thread.Sleep(SettleSeconds * 1000); + var settled = session.BufferedMs; + Console.WriteLine($" settled at target {StartTargetMs}ms: buffered={settled}ms ratio={session.DriftResamplerRatio:F6} updates={session.DriftResamplerUpdates}"); + + // Phase B: RAISE - the shipped raise path (engine hard setter for tier 2; the value the + // reads/queued-callbacks see for tier 1). Then measure depth once a second. + if (engineMixed) engine!.SetMaxLatencyMs(RaisedTargetMs); else Volatile.Write(ref target, RaisedTargetMs); + var samples = new List(); + for (var s = 0; s < MeasureSeconds; s++) + { + Thread.Sleep(1000); + samples.Add(session.BufferedMs); + if (s % 5 == 4) + Console.WriteLine($" t+{s + 1,2}s buffered={session.BufferedMs,4}ms ratio={session.DriftResamplerRatio:F6} updates={session.DriftResamplerUpdates}"); + } + + // Growth rate over the measure window (simple end-to-end slope; the per-5s prints show shape). + var growthMsPerSec = (samples[^1] - settled) / (double)MeasureSeconds; + var verdict = growthMsPerSec >= 2.0 ? "GROWS (mechanism working)" + : growthMsPerSec >= 0.5 ? "SLOW (partially working)" + : "STALLED (the field bug)"; + Console.WriteLine($" RAISE result: {settled}ms -> {samples[^1]}ms in {MeasureSeconds}s = {growthMsPerSec:F2}ms/s {verdict}"); + + // Phase C: LOWER sanity - the drain path should snap back within a couple of seconds. + if (engineMixed) engine!.SetMaxLatencyMs(StartTargetMs); + else { Volatile.Write(ref target, StartTargetMs); session.DisarmAndRequestDrain(); } + Thread.Sleep(3000); + var afterLower = session.BufferedMs; + Console.WriteLine($" LOWER result: back to target {StartTargetMs}ms -> buffered={afterLower}ms after 3s"); + Console.WriteLine(); + + results.Add($"{name}: raise {growthMsPerSec:F2}ms/s [{verdict}], lower -> {afterLower}ms"); + + stop = true; + producer.Join(2000); + consumer.Join(2000); + session.Dispose(); + } + + /// A -12 dB 440 Hz sine so the ring carries real audio (probes and concealment + /// behave as in the field; silence would short-circuit none of them but costs nothing to avoid). + private static void FillSine(byte[] block) + { + var floats = System.Runtime.InteropServices.MemoryMarshal.Cast(block.AsSpan()); + for (var i = 0; i < floats.Length; i += 2) + { + var sample = (float)(0.25 * Math.Sin(2 * Math.PI * 440 * (i / 2) / SampleRate)); + floats[i] = sample; + floats[i + 1] = sample; + } + } +} diff --git a/src/RemSound.App/SelfTest.cs b/src/RemSound.App/SelfTest.cs index 3fbf135..61c90ee 100644 --- a/src/RemSound.App/SelfTest.cs +++ b/src/RemSound.App/SelfTest.cs @@ -129,6 +129,7 @@ internal static class SelfTest RunStep(results, "Service folder repair (reproduce wrong-owner lockout → detect → repair → verify)", ServiceAccessRepairLoop); RunStep(results, "Elevated verbs carry the real user (SID pass-through) + logs stay readable", ElevatedIdentityPassThrough); RunStep(results, "About box shows only the newest releases (screen-reader-safe size)", AboutBoxNotesTrimmed); + RunStep(results, "Latency slider reaches the streams it governs (one slider = one value)", LatencySliderReachesSessions); RunStep(results, "Long-run hygiene (log rotation, crash-report cap, priority-mode scope)", LongRunHygiene); RunStep(results, "Service startup volume (boot-once decision + settings round-trip)", ServiceStartupVolume); RunStep(results, "Update install window (same-day, wraparound, retry timing)", UpdateInstallWindow); @@ -2949,6 +2950,59 @@ internal static class SelfTest return $"shipped About text: 5 versions, {shown.Length} chars (was ~70,000 — the screen-reader crash)"; } + /// The latency slider must actually govern the streams that are playing. THE 2026-08-14 + /// FIELD BUG: incoming sessions are tagged with an output LANE (WasapiLane/AsioLane — never Mixed + /// while a device is ticked), but the single slider writes RenderRoute.Mixed, and the render path + /// resolved its target per-lane — so in every classic mode the slider (and the auto-tune) wrote a + /// value nothing read, leaving the real target on the 30 ms default for the whole session. Raise + /// and lower both inert; only BothIndependent worked. Measured end-to-end by + /// --latency-lab classic (stalled -0.15ms/s → +2.07ms/s after the fix); pinned here as the + /// fast, deterministic invariant: what the slider sets IS what the session's route reads, and a + /// lower reaches the session. Also checks the two-slider mode keeps its lanes genuinely separate. + private static string? LatencySliderReachesSessions() + { + var endpoint = new IPEndPoint(IPAddress.Loopback, 47832); + + // --- Single-slider mode (WasapiOnly and every other classic mode) --- + var engine = new RemSound.Receiver.PlayoutEngine(new RemSound.Receiver.ReceiverDiagnostics()); + engine.SetIndependentLaneLatency(false); + engine.SetLaneActive(RenderRoute.WasapiLane, true); // one WASAPI output ticked... + engine.SetLaneActive(RenderRoute.AsioLane, false); // ...no ASIO, exactly as CompositeRenderBackend reports + engine.SetMaxLatencyMs(RenderRoute.Mixed, 30); // MainForm's call in classic modes + var session = engine.GetOrCreateSession(endpoint, 1, capacityBytes: 1024 * 1024); + Check(session.Route == RenderRoute.WasapiLane, + $"a stream must land on the active output lane (got {session.Route}) — the mismatch the slider used to ignore"); + + engine.SetMaxLatencyMs(RenderRoute.Mixed, 330); // the user drags the slider up + Check(engine.TargetLatencyMsFor(session.Route) == 330, + $"the target the render path reads for this stream must BE the slider's value (got {engine.TargetLatencyMsFor(session.Route)}ms for a 330ms slider)"); + Check(engine.MaxLatencyMsFor(session.Route) == 330, "the max must follow the slider too"); + + // A LOWER must reach the session (disarm + drain). Arm it first, then lower and prove the + // very next read returns nothing — that IS the disarm, and it's what refills to the new depth. + var block = new byte[48000 * 8 / 2]; // 500ms stereo float — must exceed the 330ms target, or it never arms + session.Write(block); + session.NoteFramesQueued(engine.TargetLatencyMsFor(session.Route)); + var scratch = new float[960 * 2]; + Check(session.ReadFloats(scratch, 960, 330, 330) > 0, "the session must be armed and producing before the lower"); + engine.SetMaxLatencyMs(RenderRoute.Mixed, 30); + Check(session.ReadFloats(scratch, 960, 30, 30) == 0, + "lowering the slider must disarm+drain this stream — matching on the slider's route is what made 'lower' inert"); + + // --- Two-slider mode (BothIndependent): lanes stay genuinely separate --- + var indep = new RemSound.Receiver.PlayoutEngine(new RemSound.Receiver.ReceiverDiagnostics()); + indep.SetMaxLatencyMs(RenderRoute.Mixed, 250); // whatever the single slider last held... + indep.SetIndependentLaneLatency(true); // ...seeds both lanes, so audio doesn't jump + Check(indep.TargetLatencyMsFor(RenderRoute.WasapiLane) == 250 && indep.TargetLatencyMsFor(RenderRoute.AsioLane) == 250, + "entering two-slider mode must seed both lanes from the shared value (no jump at the changeover)"); + indep.SetMaxLatencyMs(RenderRoute.WasapiLane, 40); + indep.SetMaxLatencyMs(RenderRoute.AsioLane, 8); + Check(indep.TargetLatencyMsFor(RenderRoute.WasapiLane) == 40 && indep.TargetLatencyMsFor(RenderRoute.AsioLane) == 8, + "each lane must hold its own target in two-slider mode"); + + return "one slider now governs every stream (raise + lower reach it); two-slider mode keeps its lanes separate"; + } + /// Issue #23 boot self-heal decision core. Scenario: at the boot lock screen the machine's /// speakers audibly play (Windows tune, NVDA) but a capture attached in the first seconds of boot /// taps an engine mix the logon-session audio was never wired into — the endpoint's own METER shows diff --git a/src/RemSound.Receiver/AudioReceiver.cs b/src/RemSound.Receiver/AudioReceiver.cs index b6fb13a..aeb1cac 100644 --- a/src/RemSound.Receiver/AudioReceiver.cs +++ b/src/RemSound.Receiver/AudioReceiver.cs @@ -189,6 +189,10 @@ public sealed class AudioReceiver : IDisposable try { multiOutput.Stop(); } catch { /* ignore */ } try { multiOutput.Dispose(); } catch { /* ignore */ } multiOutput = new CompositeRenderBackend(mode, asioDriverName, playoutEngine, msg => diagnosticSink?.Invoke($"output: {msg}")); + // Two latency sliders exist in BothIndependent and nowhere else; every other mode has ONE + // slider, so one latency value governs every session (see PlayoutEngine.independentLanes — + // resolving it per output lane is what made the single slider inert, 2026-08-14). + playoutEngine.SetIndependentLaneLatency(mode == AudioMode.BothIndependent); if (wasRunning) multiOutput.Start(); } @@ -1116,7 +1120,11 @@ public sealed class AudioReceiver : IDisposable try { - newSession = new StreamSession(remote, streamId, format, sp, diagnostics, _ => sp.NoteFramesQueued(playoutEngine.TargetLatencyMs), decryptor); + // Arm against the target THIS session actually plays to (its own route's), not the + // engine-wide one — in BothIndependent those differ, and arming to the wrong one + // starts playback at the wrong depth. In single-slider mode every route resolves to + // the same shared value, so this is identical to the old call there. + newSession = new StreamSession(remote, streamId, format, sp, diagnostics, _ => sp.NoteFramesQueued(playoutEngine.TargetLatencyMsFor(sp.Route)), decryptor); } catch { diff --git a/src/RemSound.Receiver/PlayoutEngine.cs b/src/RemSound.Receiver/PlayoutEngine.cs index 15fafe5..848a0b2 100644 --- a/src/RemSound.Receiver/PlayoutEngine.cs +++ b/src/RemSound.Receiver/PlayoutEngine.cs @@ -86,7 +86,7 @@ internal sealed class PlayoutEngine : IWaveProvider public volatile int TargetMs = 30; public volatile int MaxMs = 80; } - private readonly LaneLatency mixedLatency = new(); + private readonly LaneLatency sharedLatency = new(); private readonly LaneLatency wasapiLaneLatency = new(); private readonly LaneLatency asioLaneLatency = new(); // Per-lane active flag — true when an output device is ticked for that lane in @@ -201,26 +201,59 @@ internal sealed class PlayoutEngine : IWaveProvider public WaveFormat WaveFormat { get; } = WaveFormat.CreateIeeeFloatWaveFormat(MixSampleRate, MixChannels); - /// Legacy property returning the Mixed route's target. Used by code paths that - /// don't care about per-route routing (every classic mode, plus diagnostics that report - /// "the" target latency in non-BothIndependent setups). - public int TargetLatencyMs => mixedLatency.TargetMs; - /// Legacy property returning the Mixed route's max. - public int MaxLatencyMs => mixedLatency.MaxMs; + /// True only in BothIndependent, where the UI genuinely shows two latency sliders + /// (WASAPI and ASIO) and each lane must hold its own target. FALSE in every single-slider mode, + /// and then there is exactly ONE latency value — — used by every + /// session whatever output lane it happens to be tagged with. + /// + /// This flag is the fix for the 2026-08-14 field report ("the latency slider does nothing"). + /// Sessions are always tagged with an OUTPUT LANE by ReconcileReplicasLocked (WasapiLane / + /// AsioLane — never Mixed while any output device is ticked), but the single slider wrote to the + /// Mixed value, which the render path then never read. So in every classic mode the slider — and + /// the auto-tune with it — updated a value nothing consumed, while the real target sat on + /// LaneLatency's 30 ms default for the whole session: raise and lower equally inert. Only + /// BothIndependent worked, because there the slider writes WasapiLane, which IS what its sessions + /// read. Measured before/after by --latency-lab classic and pinned by the gate. The lane + /// tag says which DEVICE a session renders through; it was never meant to pick a latency knob. + private volatile bool independentLanes; + + /// Switch between one-slider and two-slider latency. Entering two-slider mode seeds both + /// lane values from the shared one so the audio doesn't jump at the changeover; leaving it hands + /// control back to the shared value. Called from AudioReceiver.SetAudioMode. + public void SetIndependentLaneLatency(bool independent) + { + if (independent && !independentLanes) + { + wasapiLaneLatency.TargetMs = asioLaneLatency.TargetMs = sharedLatency.TargetMs; + wasapiLaneLatency.MaxMs = asioLaneLatency.MaxMs = sharedLatency.MaxMs; + } + independentLanes = independent; + } + + /// The one latency in single-slider mode; in BothIndependent, the value diagnostics + /// report as "the" target (each lane's own is available via ). + public int TargetLatencyMs => sharedLatency.TargetMs; + /// The one max in single-slider mode (see ). + public int MaxLatencyMs => sharedLatency.MaxMs; /// Per-route target accessor. In BothIndependent the WASAPI and ASIO routes have /// independent targets so each lane can settle at its native latency without the other - /// pulling it. In classic modes only Mixed is meaningful; the other two routes return - /// their defaults. + /// pulling it. In every single-slider mode all routes resolve to the one shared value. public int TargetLatencyMsFor(RenderRoute route) => LatencyFor(route).TargetMs; public int MaxLatencyMsFor(RenderRoute route) => LatencyFor(route).MaxMs; - private LaneLatency LatencyFor(RenderRoute route) => route switch + /// The latency a route reads. With one slider that is ALWAYS the shared value — see + /// for why resolving this per-lane made the slider inert. + private LaneLatency LatencyFor(RenderRoute route) { - RenderRoute.WasapiLane => wasapiLaneLatency, - RenderRoute.AsioLane => asioLaneLatency, - _ => mixedLatency, - }; + if (!independentLanes) return sharedLatency; + return route switch + { + RenderRoute.WasapiLane => wasapiLaneLatency, + RenderRoute.AsioLane => asioLaneLatency, + _ => sharedLatency, + }; + } /// Aggregate buffered ms across all active sessions. Used by the App's diagnostic /// snapshot row. Per-session levels are not currently exposed (single number is enough for @@ -345,15 +378,27 @@ internal sealed class PlayoutEngine : IWaveProvider var previousTarget = lane.TargetMs; lane.MaxMs = clamped; lane.TargetMs = clamped; - if (clamped < previousTarget && drainOnLower) + if (clamped == previousTarget) return; + // Which sessions does this change actually govern? With one slider that's EVERY session + // (they all read the shared value, whatever output lane they're tagged with) — matching on + // the route here is what made "lower the slider" inert in classic modes, since the slider's + // route is Mixed and no playing session is ever tagged Mixed. + var snap = sessionsSnapshot; + foreach (var s in snap) { - // Only drain sessions on THIS route — leaves other-route sessions playing. - var snap = sessionsSnapshot; - foreach (var s in snap) + if (independentLanes && s.Route != route) continue; + if (clamped < previousTarget && drainOnLower) { - if (s.Route != route) continue; s.DisarmAndRequestDrain(); } + else if (drainOnLower) + { + // drainOnLower marks the HARD setter — a deliberate move of the user's slider (the + // auto-tune uses the soft one). A raise can't be met by dropping audio, only by + // banking it, so converge in seconds instead of the steady-state crawl; without this + // a 400 ms raise takes over two minutes to arrive and still reads as a dead slider. + s.RequestFastLatencyApproach(); + } } } diff --git a/src/RemSound.Receiver/SessionPlayout.cs b/src/RemSound.Receiver/SessionPlayout.cs index dcde6a2..e8b73d9 100644 --- a/src/RemSound.Receiver/SessionPlayout.cs +++ b/src/RemSound.Receiver/SessionPlayout.cs @@ -179,6 +179,10 @@ internal sealed class SessionPlayout : IDisposable // true drift. private double smoothedRateRatio = 1.0; private bool resamplerActivelyTracking; + // Fast-approach state (see the FastDepthBias block). Set from the UI thread via + // RequestFastLatencyApproach, cleared on the audio thread once the ring reaches the new target. + private volatile bool fastApproachUntilOnTarget; + private long lastFastApplyTicks; private long resamplerUpdatesTotal; // Scratch buffer for reading from the ring buffer in float form. Sized lazily based on @@ -236,6 +240,21 @@ internal sealed class SessionPlayout : IDisposable // ≤0.3 % pitch nudge, never a click. private const double DepthCorrectionSec = 15.0; private const double MaxDepthBias = 0.003; + // === Fast approach after a DELIBERATE latency change (2026-08-14) === + // The steady-state numbers above are deliberately sleepy: 0.3% of realtime is ~3 ms of catch-up + // per second, and the correction is only recomputed at the 10 s drift-window boundary. That's + // right for silently absorbing clock drift, and hopeless for a user who just dragged the slider + // 400 ms and wants to HEAR the delay change — it would take over two minutes to arrive, which + // reads as "the slider does nothing" even once the slider's value reaches the right place. + // So a user-initiated change (the hard setter — never the auto-tune's soft one, which keeps the + // sleepy numbers and its parked descent behaviour) engages a fast approach: a bigger rate bias, + // recomputed several times a second, until the ring is near the new target. The audio slows or + // speeds by up to FastDepthBias while it converges — an audible, deliberate glide (that's the + // point: the user asked for the change and can hear it happen), never a gap or a click. + private const double FastDepthCorrectionSec = 3.0; + private const double FastDepthBias = 0.05; // 5% => ~50 ms of catch-up per second + private const double FastApplyIntervalSec = 0.2; // recompute 5x/sec while converging + private const double FastApproachDoneMs = 15.0; // close enough — hand back to steady state // Number of stereo frames each side of a splice point that get blended when a drop or // repeat fires. Cosine crossfade over this window smooths the discontinuity into an audio // DriftDropFramesTotal / DriftRepeatFramesTotal accessors removed 2026-05-23 alongside @@ -468,6 +487,16 @@ internal sealed class SessionPlayout : IDisposable drainRequested = true; } + /// The user just moved the latency slider: converge on the new depth in seconds rather + /// than minutes (see the FastDepthBias block). Deliberate changes only — the auto-tune's soft + /// setter must NOT call this, so its gentle, parked descent behaviour is untouched. + public void RequestFastLatencyApproach() + { + fastApproachUntilOnTarget = true; + var mir = mirrors; + for (var i = 0; i < mir.Length; i++) mir[i].fastApproachUntilOnTarget = true; + } + public void Dispose() { // AudioRingBuffer is managed; nothing to free explicitly. Method present for symmetry @@ -651,6 +680,16 @@ internal sealed class SessionPlayout : IDisposable prevDriftSampleTicks = nowTicks; UpdateDriftResamplerRateIfDue(nowTicks, targetLatencyMs); + // While converging on a freshly-moved slider, re-apply the (much larger) depth correction + // several times a second instead of waiting for the 10 s drift window — otherwise the first + // seconds after the user's move do nothing at all, which is exactly what "the slider doesn't + // work" felt like. Self-clearing once the ring is within FastApproachDoneMs of target. + if (fastApproachUntilOnTarget && resamplerActivelyTracking + && (nowTicks - lastFastApplyTicks) / (double)Stopwatch.Frequency >= FastApplyIntervalSec) + { + lastFastApplyTicks = nowTicks; + ApplyDepthCorrectedRate(targetLatencyMs); + } // Read through the resampler and apply concealment on full underruns. ReadThroughResampler(output, outFrames); @@ -667,6 +706,30 @@ internal sealed class SessionPlayout : IDisposable return outFrames; } + /// Set the resampler rate to the feed-forward clock ratio plus the depth-feedback bias + /// that walks the ring toward . Shared by the steady-state + /// 10 s window and the fast approach after a deliberate slider move — the ONLY difference is how + /// hard it's allowed to pull (see the FastDepthBias block), so both paths stay one piece of + /// arithmetic rather than two that can drift apart. + private void ApplyDepthCorrectedRate(int targetLatencyMs) + { + var depthFrames = playout.BufferedBytes / MixBytesPerFrame; + var targetFrames = targetLatencyMs * MixSampleRate / 1000; + var depthError = depthFrames - targetFrames; + var fast = fastApproachUntilOnTarget; + if (fast && Math.Abs(depthError) <= FastApproachDoneMs * MixSampleRate / 1000) + { + fastApproachUntilOnTarget = false; // arrived — back to the sleepy steady-state numbers + fast = false; + } + var spreadSec = fast ? FastDepthCorrectionSec : DepthCorrectionSec; + var bias = fast ? FastDepthBias : MaxDepthBias; + var depthCorrection = Math.Clamp(depthError / (spreadSec * MixSampleRate), -bias, bias); + var appliedRatio = smoothedRateRatio + depthCorrection; + driftResampler.SetRates(MixSampleRate * appliedRatio, MixSampleRate); + Interlocked.Increment(ref resamplerUpdatesTotal); + } + /// /// If the current drift-measurement window has expired, compute the new sender-to- /// receiver rate ratio from the bytes-written and bytes-output counters, smooth it @@ -728,18 +791,7 @@ internal sealed class SessionPlayout : IDisposable // faster; < 0 biases down to refill. Clamped + spread over DepthCorrectionSec so it's a // gentle, inaudible pitch trim, not a per-sample discontinuity. No-op until the // feed-forward has a valid measurement (smoothedRateRatio is meaningless before then). - if (resamplerActivelyTracking) - { - var depthFrames = playout.BufferedBytes / MixBytesPerFrame; - var targetFrames = targetLatencyMs * MixSampleRate / 1000; - var depthError = depthFrames - targetFrames; - var depthCorrection = Math.Clamp( - depthError / (DepthCorrectionSec * MixSampleRate), - -MaxDepthBias, MaxDepthBias); - var appliedRatio = smoothedRateRatio + depthCorrection; - driftResampler.SetRates(MixSampleRate * appliedRatio, MixSampleRate); - Interlocked.Increment(ref resamplerUpdatesTotal); - } + if (resamplerActivelyTracking) ApplyDepthCorrectedRate(targetLatencyMs); // Anchor the next window. resamplerWindowStartTicks = nowTicks;