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