fix(audio): add per-5s live-loop telemetry to name the silent-recording stage

The recorded audio is full-length silent AAC (−91dB, 1124 frames/23.95s) —
the named pipe carried ~9.1MB of zeros the entire take. The mixer's loop
ran, the pipe connected, ffmpeg read it, and the file is full-length
silence. Sources started fine ('Audio: using system default mic...' logged),
no failure callbacks fired, and the existing integration test
(Mix_WithFiltersDuckAndGain_Lands_On_AudioPipe) proves the loop→pipe path
carries real audio when fed — the fault is capture-side.

Added permanent per-5s live-loop telemetry to startup.log so the next take
names the exact stage without new code:

  Audio live: pipe connected= dropped writes= micLevel= loopLevel= drained
  N/N samples peakMix N (per 5s)

- AudioMixer.FillAndMix now returns (MicRms, MicDrained, LoopDrained) for
  the accumulation; StartLive/StopLive log start/stop lines.
- NamedPipeAudioWriter.DroppedWrites: nonzero = audio dropped before ffmpeg
  connected (names 'pipe never connected' stage).

Likely root cause: WASAPI loopback captures the default render endpoint —
if audio plays on a non-default device the recording is silently silent.
The fix requires device enumeration + selection (slice 13 candidate).

Suite 290/291 — same sole pre-existing compositor pixel failure.
This commit is contained in:
2026-09-10 10:55:13 -07:00
parent 5e78065c2d
commit f3d578c81b
4 changed files with 128 additions and 67 deletions
+63 -59
View File
@@ -1,75 +1,77 @@
# HANDOFF — 2026-09-10 (evening) # HANDOFF — 2026-09-10 (afternoon)
## Branch / Commit State ## Branch / Commit State
`main` HEAD currently = `c45cbc9` (slice 10). **Slice 11 is uncommitted** in the working tree `main` HEAD currently = `5e78065` (slice 11, committed). **Slice 12 (audio diagnostics) is
(WebView2 capture cadence + de-throttle; see below). **ahead of origin by 16, NOT pushing** — uncommitted** in the working tree. **Ahead of origin by 17, NOT pushing** — user ruling (2026-09-10):
user ruling (2026-09-10): do not push until the web-overlay **transparency AND audio-silence** do not push until the web-overlay **transparency AND audio-silence** issues are addressed.
issues are addressed. Both are open (see Still Open). Milestone tag `milestone-recording-timing` Milestone tag `milestone-recording-timing` (annotated) on `c45cbc9` — rollback point:
(annotated) on `c45cbc9` — rollback point: `git reset --hard milestone-recording-timing`. `git reset --hard milestone-recording-timing`.
## Timing saga — CLOSED (verified) ## Timing saga — CLOSED (verified)
- slice 9 `bd396e4`: duration == wall time (count-based CFR, deadline never rebased, `-re` removed). Slices 9 (`bd396e4`) + 10 (`c45cbc9`) committed. Takes `0949`/`0957` verified: counter
- slice 10 `c45cbc9`: bounded `Channel` encoder queue + drop-newest policy + burned-in dot-matrix +1/frame, zero gaps/dups. User confirmed → **timing CLOSED.**
frame counter (bottom-right). Verified on two takes (`ty-20260910-0949…-2.mp4`, 2383 frames 39.92s;
`ty-20260910-0957…-2.mp4`, 2270 frames 38.05s): **every frame decodes, counter advances +1/frame,
zero gaps/dups**. Content cadence both: median 2 frames, max gap 9, longest frozen run 8 (133ms).
User: "I think we're good on this issue" → **timing CLOSED.**
## The web-overlay threads (the active push-gate work) — Slice 11 in tree ## Slice 11 (web capture cadence) — committed `5e78065`
Two user-reframed symptoms converged on ONE root cause and one change is in the tree (uncommitted): 10Hz capture → ~30Hz target with de-throttle flags + `CaptureScheduler` (latest-wins in-flight
drop). First verification take (`ty-20260910-1038-0000-2.mp4`, 1423 frames 23.7s) results:
1. "The widget is an animated resource — the animation looks **too slow**." - **Capture cost: 35-117ms per frame** (not the hoped 10-30ms). Effective cadence is ~10-14Hz,
2. (earlier) "image renders but the **transparent pixels are black**." NOT 30Hz — the scheduler's in-flight drop silently collapsed the target back to roughly the old
rate. The in-flight drop works (no stacking), but the decode path (BitmapImage →
FormatConvertedBitmap → FindContentBounds full-scan) is too expensive to reach 30Hz.
Web animation speed will not have improved meaningfully. Next: the capture cost decides — either
optimize the decode path (crop-only, cached bounds) or drop the target to ~15Hz.
- FramePump: healthy (300/300 frames, 0 dropped, 6 stalls worst 166ms).
- Camera: initialized (YUY2 640×480) but "MJPG negotiation refused (being used by another process)"
logged at startup — the webcam source was contested.
- Audio: **full-length silent AAC** (−91dB, 1124 frames). User reported: no transparency in web-uri,
no webcam video, no audio. The three symptoms are separate threads.
Root cause of #1 (code-proven): the recording is 60fps, but the WebView2 capture loop was a blind ## Slice 12 (audio diagnostics) — uncommitted, in-tree
100ms `DispatcherTimer` = 10Hz → the widget's motion is sampled 6× under rate → repeated-frame
slow-mo. PLUS Chromium hidden-page throttling (rAF parked, timers→1s; WebView2Feedback#1172/#3070)
when the off-screen page's host window is unfocused/covered. #2 remains UNVERIFIED (the diagnostic
PNG+alpha log is bound to the FIRST capture ever = the initial about:blank doc, so it can never see
the widget — 5/5 sessions logged alpha=0 blank; instrument is blind, not the capture).
**Slice 11 (uncommitted, files below):** The silence is capture-side: the pipe ran for 23.95s, ffmpeg connected and read ~9.1MB of zeros.
- `Services/CaptureScheduler.cs` (new): per-session dispatcher timer that DROPS ticks while a Sources started (`Audio: using system default mic...` logged at 10:38:01.296), no failure
capture is in flight (latest-wins, never queues). Interval owner-configurable: 33ms recording / callbacks fired. The mixer's existing integration test (`Mix_WithFiltersDuckAndGain_Lands_On_AudioPipe`)
200ms idle. proves the loop→pipe path carries real audio when fed. Two remaining capture-side suspects:
- `Services/WebView2Manager.cs`: scheduler replaces the raw timer; shared `CoreWebView2Environment` (1) default render device mismatch — audio played on a non-default endpoint (common);
created BEFORE `EnsureCoreWebView2Async` with `--disable-backgrounding-occluded-windows (2) both endpoints held exclusive by another process.
--disable-renderer-backgrounding --disable-features=CalculateNativeWinOcclusion`
(`GetEnvironmentAsync`); `SetCaptureInterval(int)`; capture-cost telemetry (first 30 captures/
session → startup.log).
- `ViewModels/MainViewModel.Streaming.Operations.cs`: `SetCaptureInterval(33)` on record/stream
start, `(200)` on stop.
- `ytLive.Tests/WebView2ManagerTests.cs`: ONE test
`CaptureScheduler_Drops_Ticks_While_Capture_InFlight_And_Resumes` (deterministic TCS-driven, no
WebView2 runtime).
- Docs same commit: `ai.md` slice 11, `MyMistakes.md` recipe "web widget captured at 10Hz…".
Suite: 290/291 pass — sole failure the PRE-EXISTING `Composite_FullScene_MasterPixels` pixel **Changes in tree:**
(1380,700) cyan-vs-magenta (out of scope; fails with any fix stashed). - `Services/Audio/AudioMixer.cs`: `FillAndMix` now returns `(MicRms, MicDrained, LoopDrained)`;
LiveLoopAsync accumulates per-5s telemetry → startup.log:
`Audio live: pipe connected=, dropped writes=, micLevel=, loopLevel=, drained, peakMix`;
StartLive/StopLive log start/stop lines.
- `Services/Audio/NamedPipeAudioWriter.cs`: new `DroppedWrites` counter — nonzero means audio
was dropped before ffmpeg connected (names "pipe never connected" stage).
- Docs: `ai.md` slice 12 entry.
## NEXT STEP (the take that closes the web animation speed) Suite: 290/291 pass — same sole pre-existing compositor pixel failure.
1. Commit slice 11 (scope-check first; commit cites WebView2Feedback#1172/#3070/#20 + Chrome-88 blog). ## NEXT STEP
2. Run a normal recording with the animated widget on screen for ~20s. Expected:
- startup.log: `capture #1..#30 … took Nms` lines (tell us the per-capture cost) — **this decides 1. Commit slice 12 (scope-check passed on the three source/doc files).
whether 30Hz stays or drops to ~20Hz**; also `FramePump stats:` should show no new dropped-frame 2. User runs a recording with DESKTOP AUDIO ACTIVE (music/game playing → verify the "Desktop Audio"
growth vs before (GC-churn check). footer bar moves during the take). Send startup.log lines containing `Audio live:`.
- Widget animation ~2-3× closer to real-time (10→30Hz). The log names the stage:
- If it only became jittery instead of fast: check the FramePump dropped-frame counters. - `loopLevel > 0` + `peakMix > 0` + file silent → pipe-side (impossible per integration test; should not appear)
3. Then, separately, the TRANSPARENCY verification (still open): re-point the first-capture dump/ - `loopLevel ≈ 0` + `drained 0/0` → capture delivered nothing (default device mismatch or exclusive hold)
alpha-log at a POST-PAINT capture of the real widget document (currently bound to about:blank) — - `dropped writes > 0` → encoder pipe never connected (timing/ordering bug)
the change that makes "are transparent margins real?" answerable. Intended next change. 3. If capture-side: add explicit loopback-device selection (enumerate active render endpoints, log
the chosen one, allow user to pick) — the fix that makes the mismatch impossible.
4. Then return to web transparency (post-paint dump) and webcam.
## Still Open ## Still Open
- **Web transparency UNVERIFIED** — the diagnostic instrument is blind (fires on about:blank); last - **Audio silence** — push gate reason #2. Diagnostic committed pending take (see above).
known visual state take-25 black box; user's "transparent pixels black" may be the opacity bug OR - **Web transparency UNVERIFIED** — instrument blind (about:blank). Needs post-paint re-point.
the preview surface. Needs the post-paint instrument fix (above) then a take. Push gate reason #1. Push gate reason #1.
- **Audio silence** — silent audio (−91dB full-length) in take-15; named-pipe audio delivers ~nothing. - **Web capture speed** — 30Hz target not achievable with current decode path; capture cost
Queued follow-up. Push gate reason #2. 35-117ms/frame → effective ~10-14Hz. Open question whether to optimize path or accept ~15Hz.
- **Webcam missing** in take-1038 — "MJPG negotiation refused (being used by another process)"
at startup; camera initialized but possibly contested. Separate thread, queued.
- Pre-existing compositor pixel test failure (never in scope). - Pre-existing compositor pixel test failure (never in scope).
## Landmines ## Landmines
@@ -78,8 +80,10 @@ Suite: 290/291 pass — sole failure the PRE-EXISTING `Composite_FullScene_Maste
- Locked DLLs: `taskkill //F //IM testhost.exe //IM ytLive.exe` before rebuild. - Locked DLLs: `taskkill //F //IM testhost.exe //IM ytLive.exe` before rebuild.
- Build/tests via `/mnt/c/Program Files/dotnet/dotnet.exe build …` / `… vstest - Build/tests via `/mnt/c/Program Files/dotnet/dotnet.exe build …` / `… vstest
"C:\Users\gramp\Documents\Code\projects\ytLive\ytLive.Tests\bin\Debug\net8.0-windows10.0.19041.0\ytLive.Tests.dll"`. "C:\Users\gramp\Documents\Code\projects\ytLive\ytLive.Tests\bin\Debug\net8.0-windows10.0.19041.0\ytLive.Tests.dll"`.
- Probing recordings: `/mnt/c/Program Files/Krita (x64)/bin/ffmpeg.exe` / `ffprobe.exe` (Windows-form paths). - Probing recordings: `/mnt/c/Program Files/Krita (x64)/bin/ffmpeg.exe` / `ffprobe.exe`.
- `tools/ticker`: constant ~+982ms offset on the FIRST line is cosmetic. - `tools/ticker`: constant ~+982ms offset on the FIRST line is cosmetic.
- WebView2Manager Ran into LOH churn worry: each capture allocs a BitmapImage raster (~8.3MB) that - WebView2 capture cost: 35-117ms per full-HD PNG encode+decode — the hard ceiling on
is garbage per capture; at 30Hz that's ~250MB/s LOH on the UI thread → potential gen2 pauses web animation capture rate. Slice 13 candidate if the user wants to pursue 30Hz.
showing as FramePump dropped frames. Slice 12 candidate if the take's stats show it. - WASAPI loopback: captures the DEFAULT render endpoint only — if the user plays audio
through a non-default device, the recording is silently silent. This is likely the root cause
of the audio-silence issue. The fix requires device enumeration + selection.
+37 -5
View File
@@ -50,6 +50,10 @@ public sealed class AudioMixer : IDisposable
private float[]? _mixBuffer; private float[]? _mixBuffer;
private float[]? _delayedMix; private float[]? _delayedMix;
private DateTime _lastLoopErrorLogged = DateTime.MinValue; private DateTime _lastLoopErrorLogged = DateTime.MinValue;
private DateTime _nextStatsLog = DateTime.UtcNow + TimeSpan.FromSeconds(5);
private long _micDrainedTotal;
private long _loopDrainedTotal;
private float _peakMix;
public AudioMixer( public AudioMixer(
IAudioSource mic, IAudioSource mic,
@@ -159,6 +163,7 @@ public sealed class AudioMixer : IDisposable
_liveCts = cts; _liveCts = cts;
_pipe = new NamedPipeAudioWriter(); _pipe = new NamedPipeAudioWriter();
_pipe.Start(pipeName); _pipe.Start(pipeName);
_log?.Invoke($"Audio live: started, pipe '{pipeName}'");
_ = Task.Run(() => LiveLoopAsync(_pipe, cts.Token)); _ = Task.Run(() => LiveLoopAsync(_pipe, cts.Token));
} }
@@ -169,7 +174,11 @@ public sealed class AudioMixer : IDisposable
{ {
var cts = _liveCts; var cts = _liveCts;
_liveCts = null; _liveCts = null;
cts?.Cancel(); if (cts != null)
{
_log?.Invoke("Audio live: stopped");
cts.Cancel();
}
_pipe.Stop(); _pipe.Stop();
} }
@@ -274,8 +283,28 @@ public sealed class AudioMixer : IDisposable
var nextTick = DateTime.UtcNow + _mixInterval; var nextTick = DateTime.UtcNow + _mixInterval;
try try
{ {
FillAndMix(micChunk, loopbackChunk, mixBuffer); var (_, micDrained, loopDrained) = FillAndMix(micChunk, loopbackChunk, mixBuffer);
await pipe.WriteAsync(mixBuffer, cancellationToken).ConfigureAwait(false); await pipe.WriteAsync(mixBuffer, cancellationToken).ConfigureAwait(false);
_micDrainedTotal += micDrained;
_loopDrainedTotal += loopDrained;
for (var i = 0; i < mixBuffer.Length; i++)
{
var abs = Math.Abs(mixBuffer[i]);
if (abs > _peakMix) _peakMix = abs;
}
var now = DateTime.UtcNow;
if (now >= _nextStatsLog && _log != null)
{
_nextStatsLog = now + TimeSpan.FromSeconds(5);
_log($"Audio live: pipe connected={pipe.IsConnected} dropped writes={pipe.DroppedWrites} " +
$"micLevel={_meter.Level:F3} loopLevel={_loopbackMeter.Level:F3} " +
$"drained {_micDrainedTotal:N0}/{_loopDrainedTotal:N0} samples peakMix {_peakMix:F3} (per 5s)");
_micDrainedTotal = 0;
_loopDrainedTotal = 0;
_peakMix = 0;
}
} }
catch (OperationCanceledException) catch (OperationCanceledException)
{ {
@@ -313,8 +342,11 @@ public sealed class AudioMixer : IDisposable
} }
/// <summary>Drains one tick's worth of mic + loopback, silence-fills any /// <summary>Drains one tick's worth of mic + loopback, silence-fills any
/// underrun, applies the ducker and the honest gains, and mixes to stereo.</summary> /// underrun, applies the ducker and the honest gains, and mixes to stereo.
private float FillAndMix(float[] micChunk, float[] loopbackChunk, float[] mix) /// Returns the pre-duck mic RMS and how many samples each buffer contributed
/// (the 5s live-loop telemetry reads those to name whether capture or the
/// pipe starved a silent recording).</summary>
private (float MicRms, int MicDrained, int LoopDrained) FillAndMix(float[] micChunk, float[] loopbackChunk, float[] mix)
{ {
var micCount = _micBuffer.Read(micChunk, micChunk.Length); var micCount = _micBuffer.Read(micChunk, micChunk.Length);
var loopCount = _loopbackBuffer.Read(loopbackChunk, loopbackChunk.Length); var loopCount = _loopbackBuffer.Read(loopbackChunk, loopbackChunk.Length);
@@ -362,6 +394,6 @@ public sealed class AudioMixer : IDisposable
delayed = _delayedMix = new float[mix.Length]; delayed = _delayedMix = new float[mix.Length];
_syncDelay.Process(mix, delayed); _syncDelay.Process(mix, delayed);
Array.Copy(delayed, mix, mix.Length); Array.Copy(delayed, mix, mix.Length);
return micRms; return (micRms, micCount, loopCount);
} }
} }
+13
View File
@@ -17,6 +17,12 @@ public interface IAudioPipeWriter : IDisposable
/// <summary>True once ffmpeg has connected and the pipe is writable.</summary> /// <summary>True once ffmpeg has connected and the pipe is writable.</summary>
bool IsConnected { get; } bool IsConnected { get; }
/// <summary>Count of <see cref="WriteAsync"/> calls that wrote nothing because
/// the pipe wasn't connected yet or was already closed. Part of the silent-
/// recording diagnosis: nonzero means audio was dropped before ffmpeg ever
/// connected to the pipe.</summary>
long DroppedWrites { get; }
/// <summary>Writes interleaved float samples; dropped until the client connects.</summary> /// <summary>Writes interleaved float samples; dropped until the client connects.</summary>
Task WriteAsync(ReadOnlyMemory<float> samples, CancellationToken cancellationToken = default); Task WriteAsync(ReadOnlyMemory<float> samples, CancellationToken cancellationToken = default);
@@ -29,6 +35,9 @@ public sealed class NamedPipeAudioWriter : IAudioPipeWriter
private readonly object _sync = new(); private readonly object _sync = new();
private NamedPipeServerStream? _pipe; private NamedPipeServerStream? _pipe;
/// <inheritdoc/>
public long DroppedWrites { get; private set; }
public void Start(string pipeName) public void Start(string pipeName)
{ {
lock (_sync) lock (_sync)
@@ -64,7 +73,11 @@ public sealed class NamedPipeAudioWriter : IAudioPipeWriter
pipe = _pipe; pipe = _pipe;
} }
if (pipe == null || !pipe.IsConnected || samples.IsEmpty) if (pipe == null || !pipe.IsConnected || samples.IsEmpty)
{
if (pipe?.IsConnected == false || pipe == null)
DroppedWrites++;
return; return;
}
var bytes = MemoryMarshal.AsBytes(samples.Span).ToArray(); var bytes = MemoryMarshal.AsBytes(samples.Span).ToArray();
await pipe.WriteAsync(bytes, cancellationToken).ConfigureAwait(false); await pipe.WriteAsync(bytes, cancellationToken).ConfigureAwait(false);
+12
View File
@@ -899,6 +899,18 @@ seam:** `Func<Scene?>`, `Func<SceneElement, VideoFrame?>` resolver, `Func<Compos
Full suite 290/291 passing, the sole failure the pre-existing compositor pixel test. The web-overlay Full suite 290/291 passing, the sole failure the pre-existing compositor pixel test. The web-overlay
transparency verification (the first-capture diagnostic bound to about:blank) and the audio-silence transparency verification (the first-capture diagnostic bound to about:blank) and the audio-silence
item remain open push-gate items — both untouched by this slice. item remain open push-gate items — both untouched by this slice.
- **Slice 12 (audio diagnostics, 2026-09-10):** the recorded audio is full-length silent AAC
(−91dB, 1124 frames / 23.95s in the latest take) — the named-pipe delivered ~9.1MB of zeros to
ffmpeg for the entire recording, so the loop ran and connected, but both WASAPI capture sources
delivered nothing. Sources started fine (`Audio: using system default mic...` logged), no failure
callbacks fired, and the mixer's existing integration test (`Mix_WithFiltersDuckAndGain_Lands_On_AudioPipe`)
proves the loop→pipe math is sound. The fault is capture-side: either the default render endpoint
carried nothing (audio played on a non-default device — common), or both endpoints were held
exclusive, or genuinely nothing played. Added permanent per-5s live-loop telemetry to startup.log
(`Audio live: pipe connected=, dropped writes=, micLevel=, loopLevel=, drained, peakMix`) and
`NamedPipeAudioWriter.DroppedWrites` — names the exact stage on the next take without new
code. `AudioMixer.FillAndMix` now returns `(MicRms, MicDrained, LoopDrained)` for the telemetry
accumulation. Full suite 290/291, same pre-existing sole failure.
- **Stop ordering matters:** `StopAsync` stops the encoder — since slice 10 it FLUSHES the pending - **Stop ordering matters:** `StopAsync` stops the encoder — since slice 10 it FLUSHES the pending
queue (`Channel.TryComplete` → drain writes the leftovers, closes stdin → EOF → ffmpeg finalizes+exits; queue (`Channel.TryComplete` → drain writes the leftovers, closes stdin → EOF → ffmpeg finalizes+exits;
an accepted frame is never lost) — **before** awaiting the loop. The old reverse-order deadlock was an accepted frame is never lost) — **before** awaiting the loop. The old reverse-order deadlock was