From 25d5416a93a17ef4ea1a7778df0b1025fcf95d12 Mon Sep 17 00:00:00 2001 From: gramps Date: Mon, 5 Oct 2026 13:31:42 -0700 Subject: [PATCH] Timing: add per-stage counters to FramePump stats Add timing for social bar, ticker, flash delegates and scratch acquire, and extend the 5s stats line to report them (ms per render). No behavior change, only measurement. --- Services/Encoder/FramePump.cs | 50 ++++++++++++++++++++--------------- 1 file changed, 29 insertions(+), 21 deletions(-) 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) {