diff --git a/HANDOFF.md b/HANDOFF.md index 9400461..ffb12c9 100644 --- a/HANDOFF.md +++ b/HANDOFF.md @@ -1,75 +1,77 @@ -# HANDOFF — 2026-09-10 (evening) +# HANDOFF — 2026-09-10 (afternoon) ## Branch / Commit State -`main` HEAD currently = `c45cbc9` (slice 10). **Slice 11 is uncommitted** in the working tree -(WebView2 capture cadence + de-throttle; see below). **ahead of origin by 16, NOT pushing** — -user ruling (2026-09-10): do not push until the web-overlay **transparency AND audio-silence** -issues are addressed. Both are open (see Still Open). Milestone tag `milestone-recording-timing` -(annotated) on `c45cbc9` — rollback point: `git reset --hard milestone-recording-timing`. +`main` HEAD currently = `5e78065` (slice 11, committed). **Slice 12 (audio diagnostics) is +uncommitted** in the working tree. **Ahead of origin by 17, NOT pushing** — user ruling (2026-09-10): +do not push until the web-overlay **transparency AND audio-silence** issues are addressed. +Milestone tag `milestone-recording-timing` (annotated) on `c45cbc9` — rollback point: +`git reset --hard milestone-recording-timing`. ## Timing saga — CLOSED (verified) -- slice 9 `bd396e4`: duration == wall time (count-based CFR, deadline never rebased, `-re` removed). -- slice 10 `c45cbc9`: bounded `Channel` encoder queue + drop-newest policy + burned-in dot-matrix - 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.** +Slices 9 (`bd396e4`) + 10 (`c45cbc9`) committed. Takes `0949`/`0957` verified: counter ++1/frame, zero gaps/dups. User confirmed → **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**." -2. (earlier) "image renders but the **transparent pixels are black**." +- **Capture cost: 35-117ms per frame** (not the hoped 10-30ms). Effective cadence is ~10-14Hz, + 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 -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 12 (audio diagnostics) — uncommitted, in-tree -**Slice 11 (uncommitted, files below):** -- `Services/CaptureScheduler.cs` (new): per-session dispatcher timer that DROPS ticks while a - capture is in flight (latest-wins, never queues). Interval owner-configurable: 33ms recording / - 200ms idle. -- `Services/WebView2Manager.cs`: scheduler replaces the raw timer; shared `CoreWebView2Environment` - created BEFORE `EnsureCoreWebView2Async` with `--disable-backgrounding-occluded-windows - --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…". +The silence is capture-side: the pipe ran for 23.95s, ffmpeg connected and read ~9.1MB of zeros. +Sources started (`Audio: using system default mic...` logged at 10:38:01.296), no failure +callbacks fired. The mixer's existing integration test (`Mix_WithFiltersDuckAndGain_Lands_On_AudioPipe`) +proves the loop→pipe path carries real audio when fed. Two remaining capture-side suspects: +(1) default render device mismatch — audio played on a non-default endpoint (common); +(2) both endpoints held exclusive by another process. -Suite: 290/291 pass — sole failure the PRE-EXISTING `Composite_FullScene_MasterPixels` pixel -(1380,700) cyan-vs-magenta (out of scope; fails with any fix stashed). +**Changes in tree:** +- `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). -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 - whether 30Hz stays or drops to ~20Hz**; also `FramePump stats:` should show no new dropped-frame - growth vs before (GC-churn check). - - Widget animation ~2-3× closer to real-time (10→30Hz). - - If it only became jittery instead of fast: check the FramePump dropped-frame counters. -3. Then, separately, the TRANSPARENCY verification (still open): re-point the first-capture dump/ - alpha-log at a POST-PAINT capture of the real widget document (currently bound to about:blank) — - the change that makes "are transparent margins real?" answerable. Intended next change. +## NEXT STEP + +1. Commit slice 12 (scope-check passed on the three source/doc files). +2. User runs a recording with DESKTOP AUDIO ACTIVE (music/game playing → verify the "Desktop Audio" + footer bar moves during the take). Send startup.log lines containing `Audio live:`. + The log names the stage: + - `loopLevel > 0` + `peakMix > 0` + file silent → pipe-side (impossible per integration test; should not appear) + - `loopLevel ≈ 0` + `drained 0/0` → capture delivered nothing (default device mismatch or exclusive hold) + - `dropped writes > 0` → encoder pipe never connected (timing/ordering bug) +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 -- **Web transparency UNVERIFIED** — the diagnostic instrument is blind (fires on about:blank); last - known visual state take-25 black box; user's "transparent pixels black" may be the opacity bug OR - the preview surface. Needs the post-paint instrument fix (above) then a take. Push gate reason #1. -- **Audio silence** — silent audio (−91dB full-length) in take-15; named-pipe audio delivers ~nothing. - Queued follow-up. Push gate reason #2. +- **Audio silence** — push gate reason #2. Diagnostic committed pending take (see above). +- **Web transparency UNVERIFIED** — instrument blind (about:blank). Needs post-paint re-point. + Push gate reason #1. +- **Web capture speed** — 30Hz target not achievable with current decode path; capture cost + 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). ## 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. - 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"`. -- 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. -- WebView2Manager Ran into LOH churn worry: each capture allocs a BitmapImage raster (~8.3MB) that - is garbage per capture; at 30Hz that's ~250MB/s LOH on the UI thread → potential gen2 pauses - showing as FramePump dropped frames. Slice 12 candidate if the take's stats show it. \ No newline at end of file +- WebView2 capture cost: 35-117ms per full-HD PNG encode+decode — the hard ceiling on + web animation capture rate. Slice 13 candidate if the user wants to pursue 30Hz. +- 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. diff --git a/Services/Audio/AudioMixer.cs b/Services/Audio/AudioMixer.cs index d99a062..c3b7498 100644 --- a/Services/Audio/AudioMixer.cs +++ b/Services/Audio/AudioMixer.cs @@ -50,6 +50,10 @@ public sealed class AudioMixer : IDisposable private float[]? _mixBuffer; private float[]? _delayedMix; private DateTime _lastLoopErrorLogged = DateTime.MinValue; + private DateTime _nextStatsLog = DateTime.UtcNow + TimeSpan.FromSeconds(5); + private long _micDrainedTotal; + private long _loopDrainedTotal; + private float _peakMix; public AudioMixer( IAudioSource mic, @@ -159,6 +163,7 @@ public sealed class AudioMixer : IDisposable _liveCts = cts; _pipe = new NamedPipeAudioWriter(); _pipe.Start(pipeName); + _log?.Invoke($"Audio live: started, pipe '{pipeName}'"); _ = Task.Run(() => LiveLoopAsync(_pipe, cts.Token)); } @@ -169,7 +174,11 @@ public sealed class AudioMixer : IDisposable { var cts = _liveCts; _liveCts = null; - cts?.Cancel(); + if (cts != null) + { + _log?.Invoke("Audio live: stopped"); + cts.Cancel(); + } _pipe.Stop(); } @@ -274,8 +283,28 @@ public sealed class AudioMixer : IDisposable var nextTick = DateTime.UtcNow + _mixInterval; try { - FillAndMix(micChunk, loopbackChunk, mixBuffer); + var (_, micDrained, loopDrained) = FillAndMix(micChunk, loopbackChunk, mixBuffer); 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) { @@ -313,8 +342,11 @@ public sealed class AudioMixer : IDisposable } /// Drains one tick's worth of mic + loopback, silence-fills any - /// underrun, applies the ducker and the honest gains, and mixes to stereo. - private float FillAndMix(float[] micChunk, float[] loopbackChunk, float[] mix) + /// underrun, applies the ducker and the honest gains, and mixes to stereo. + /// 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). + private (float MicRms, int MicDrained, int LoopDrained) FillAndMix(float[] micChunk, float[] loopbackChunk, float[] mix) { var micCount = _micBuffer.Read(micChunk, micChunk.Length); var loopCount = _loopbackBuffer.Read(loopbackChunk, loopbackChunk.Length); @@ -362,6 +394,6 @@ public sealed class AudioMixer : IDisposable delayed = _delayedMix = new float[mix.Length]; _syncDelay.Process(mix, delayed); Array.Copy(delayed, mix, mix.Length); - return micRms; + return (micRms, micCount, loopCount); } } diff --git a/Services/Audio/NamedPipeAudioWriter.cs b/Services/Audio/NamedPipeAudioWriter.cs index f898e8b..0b872dd 100644 --- a/Services/Audio/NamedPipeAudioWriter.cs +++ b/Services/Audio/NamedPipeAudioWriter.cs @@ -17,6 +17,12 @@ public interface IAudioPipeWriter : IDisposable /// True once ffmpeg has connected and the pipe is writable. bool IsConnected { get; } + /// Count of 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. + long DroppedWrites { get; } + /// Writes interleaved float samples; dropped until the client connects. Task WriteAsync(ReadOnlyMemory samples, CancellationToken cancellationToken = default); @@ -29,6 +35,9 @@ public sealed class NamedPipeAudioWriter : IAudioPipeWriter private readonly object _sync = new(); private NamedPipeServerStream? _pipe; + /// + public long DroppedWrites { get; private set; } + public void Start(string pipeName) { lock (_sync) @@ -64,7 +73,11 @@ public sealed class NamedPipeAudioWriter : IAudioPipeWriter pipe = _pipe; } if (pipe == null || !pipe.IsConnected || samples.IsEmpty) + { + if (pipe?.IsConnected == false || pipe == null) + DroppedWrites++; return; + } var bytes = MemoryMarshal.AsBytes(samples.Span).ToArray(); await pipe.WriteAsync(bytes, cancellationToken).ConfigureAwait(false); diff --git a/ai.md b/ai.md index 33b44dd..697e3cc 100644 --- a/ai.md +++ b/ai.md @@ -896,9 +896,21 @@ seam:** `Func`, `Func` resolver, `Func