diff --git a/Services/Encoder/FramePump.cs b/Services/Encoder/FramePump.cs index 0bc8e84..312d6a1 100644 --- a/Services/Encoder/FramePump.cs +++ b/Services/Encoder/FramePump.cs @@ -333,11 +333,14 @@ public sealed class FramePump : IDisposable // black box — the stats line now reports resolver time separately so a take // names the stage (get-frame vs blit) instead of feeding another guess. var resolveSw = new System.Diagnostics.Stopwatch(); - long renderTicks = 0, submitTicks = 0, resolveTicks = 0, waitTicks = 0, worstRender = 0, worstSubmit = 0; + long renderTicks = 0, submitTicks = 0, resolveTicks = 0, waitTicks = 0; + long socialBarTicks = 0, tickerTicks = 0, flashTicks = 0, acquireTicks = 0; + long worstRender = 0, worstSubmit = 0; int statFrames = 0; int stalls = 0; long lastCacheHits = 0, lastCacheRenders = 0; var statsNext = DateTime.UtcNow + TimeSpan.FromSeconds(5); + bool _loggedStartDetail = false; // Real-render accounting (UNIT 0, 2026-10-05): every average above was // divided by statFrames — the number of frames SUBMITTED, which deadline @@ -379,20 +382,26 @@ public sealed class FramePump : IDisposable lastCacheRenders = CacheRenders; if (hits > 0 || renders > 0) cacheDetail = $", cache {renders}R/{hits}H"; } + double freq = System.Diagnostics.Stopwatch.Frequency; _log?.Invoke(statFrames == 0 ? "FramePump stats: NO frames produced in 5s (loop stalled?)" + (detail.Length > 0 ? " | " + detail : "") : $"FramePump stats: {statFrames}/{target:F0} frames per 5s from {statRenders} renders, " + - $"avg render {renderTicks / (double)System.Diagnostics.Stopwatch.Frequency * 1000 / Math.Max(1, statRenders):F1}ms " + - $"(resolve {resolveTicks / (double)System.Diagnostics.Stopwatch.Frequency * 1000 / Math.Max(1, statRenders):F1}), " + - $"avg submit {submitTicks / (double)System.Diagnostics.Stopwatch.Frequency * 1000 / statFrames:F1}ms, " - + $"avg wait {waitTicks / (double)System.Diagnostics.Stopwatch.Frequency * 1000 / Math.Max(1, statRenders):F1}ms, " - + $"worst render {worstRender / (double)System.Diagnostics.Stopwatch.Frequency * 1000:F1}ms, " - + $"worst submit {worstSubmit / (double)System.Diagnostics.Stopwatch.Frequency * 1000:F1}ms, " + $"avg render {renderTicks / freq * 1000 / Math.Max(1, statRenders):F1}ms " + + $"(resolve {resolveTicks / freq * 1000 / Math.Max(1, statRenders):F1}, " + + $"social {socialBarTicks / freq * 1000 / Math.Max(1, statRenders):F2}ms, " + + $"ticker {tickerTicks / freq * 1000 / Math.Max(1, statRenders):F2}ms, " + + $"flash {flashTicks / freq * 1000 / Math.Max(1, statRenders):F2}ms, " + + $"acq {acquireTicks / freq * 1000 / Math.Max(1, statRenders):F2}ms), " + + $"avg submit {submitTicks / freq * 1000 / statFrames:F1}ms, " + + $"avg wait {waitTicks / freq * 1000 / Math.Max(1, statRenders):F1}ms, " + + $"worst render {worstRender / freq * 1000:F1}ms, " + + $"worst submit {worstSubmit / freq * 1000:F1}ms, " + $"dropped {dropped}, stalls {stalls}{cacheDetail}, {webcamCadence.Summarize().Describe("webcam")}" + (detail.Length > 0 ? " | " + detail : "")); worstRender = 0; worstSubmit = 0; renderTicks = submitTicks = resolveTicks = waitTicks = 0; + socialBarTicks = tickerTicks = flashTicks = acquireTicks = 0; statFrames = 0; statRenders = 0; stalls = 0; @@ -438,26 +447,25 @@ public sealed class FramePump : IDisposable : compositorOptions.SourceRectHeight - barFrame.Height; } - // The alert ticker is a per-frame overlay (it scrolls while an alert - // plays), NEVER baked into the static base. Lawn-mower seam: read it - // each tick and let the compositor pin it to the very top. - var tickerFrame = _alertTicker?.Invoke(); - - // The free-tier branding credit. Read per-frame for the same reason - // as the ticker: it fades and sits on a fresh random spot, so it can - // never live in the baked base or the blit-on-change cache. - var flashFrame = _brandFlash?.Invoke(); + var sw = System.Diagnostics.Stopwatch.StartNew(); + VideoFrame? tickerFrame = _alertTicker?.Invoke(); + tickerTicks += sw.ElapsedTicks; + sw.Restart(); + VideoFrame? flashFrame = _brandFlash?.Invoke(); + flashTicks += sw.ElapsedTicks; + sw.Restart(); + var (barFrame2, position2) = (_socialBar == null ? (null, SocialBarPosition.Bottom) : _socialBar()); + socialBarFrame = barFrame2; + socialBarTop = barFrame2 == null ? 0 : (position2 == SocialBarPosition.Top ? 0 : compositorOptions.SourceRectHeight - barFrame2.Height); + socialBarTicks += sw.ElapsedTicks; VideoFrame frame; var scratchSize = compositorOptions.SourceRectWidth * compositorOptions.SourceRectHeight * 4; - // The transition "from" frame lives in TransitionService.FromFrame - // (captured at Start by the VM). The old per-tick fromScene render - // here was dead weight — a full extra scene composite every - // transition tick that BlendFrame never read; removed with the - // pooling change because its buffer's only consumer was its own release. renderSw.Restart(); + sw.Restart(); var scratch = AcquireScratch(scratchSize); + acquireTicks += sw.ElapsedTicks; frame = RenderScene(scene, compositorOptions, socialBarFrame, socialBarTop, tickerFrame, flashFrame, scratch, TimedResolver); if (_transition is { Active: true } transition) {