chore(pump): per-stage timing stats — render vs submit, 5s windows

Take-two forensics: rawvideo carries no per-frame timestamps — ffmpeg stamps frames
by ARRIVAL at the declared fps, so a 2fps producer yields a 30x time-lapse, 0.6s-long
'60fps' file with zero errors anywhere (explains the creator's accelerated webcam
motion + truncated length observations). The pump now logs frames-produced-vs-target
per 5s with the avg render/submit split — take three names the slow stage instead
of us theorizing. FramePumpTests 9/9. (Multi-commit working unit: remaining declared
files land in the next commit.)
This commit is contained in:
2026-09-01 22:25:02 -07:00
parent 8dcaee0b5b
commit 97ffc426fe
+32
View File
@@ -218,6 +218,30 @@ public sealed class FramePump : IDisposable
var interval = TimeSpan.FromSeconds(1d / Math.Max(1, options.Fps)); var interval = TimeSpan.FromSeconds(1d / Math.Max(1, options.Fps));
var lastTick = System.Diagnostics.Stopwatch.StartNew(); var lastTick = System.Diagnostics.Stopwatch.StartNew();
// Stage timing (2026-09-01, take two): rawvideo carries no per-frame
// timestamps — ffmpeg stamps frames by ARRIVAL at the declared fps. A producer
// slower than the declared rate yields a time-lapsed, short file (observed:
// 39 frames in 27 wall-seconds ≈ 30x at 60fps) with no error anywhere.
// Log the render/submit split every 5s so the next take names the stage.
var renderSw = new System.Diagnostics.Stopwatch();
var submitSw = new System.Diagnostics.Stopwatch();
long renderTicks = 0, submitTicks = 0;
int statFrames = 0;
var statsNext = DateTime.UtcNow + TimeSpan.FromSeconds(5);
void ReportStats()
{
if (DateTime.UtcNow < statsNext) return;
var target = 5d / interval.TotalSeconds; // frames expected per window
_log?.Invoke(statFrames == 0
? "FramePump stats: NO frames produced in 5s (loop stalled?)"
: $"FramePump stats: {statFrames}/{target:F0} frames per 5s, " +
$"avg render {renderTicks / (double)System.Diagnostics.Stopwatch.Frequency * 1000 / statFrames:F1}ms, " +
$"avg submit {submitTicks / (double)System.Diagnostics.Stopwatch.Frequency * 1000 / statFrames:F1}ms");
renderTicks = submitTicks = 0;
statFrames = 0;
statsNext = DateTime.UtcNow + TimeSpan.FromSeconds(5);
}
try try
{ {
while (!ct.IsCancellationRequested) while (!ct.IsCancellationRequested)
@@ -239,6 +263,7 @@ public sealed class FramePump : IDisposable
} }
VideoFrame frame; VideoFrame frame;
renderSw.Restart();
if (_transition is { Active: true } transition && _fromSceneProvider != null) if (_transition is { Active: true } transition && _fromSceneProvider != null)
{ {
var fromScene = _fromSceneProvider(); var fromScene = _fromSceneProvider();
@@ -255,11 +280,18 @@ public sealed class FramePump : IDisposable
frame = RenderScene(scene, compositorOptions, socialBarFrame, socialBarTop); frame = RenderScene(scene, compositorOptions, socialBarFrame, socialBarTop);
lastTick.Restart(); lastTick.Restart();
} }
renderSw.Stop();
renderTicks += renderSw.ElapsedTicks;
IFfmpegEncoder? encoder; IFfmpegEncoder? encoder;
lock (_gate) encoder = _encoder; lock (_gate) encoder = _encoder;
if (encoder == null) break; if (encoder == null) break;
submitSw.Restart();
await encoder.SubmitFrameAsync(frame, ct); await encoder.SubmitFrameAsync(frame, ct);
submitSw.Stop();
submitTicks += submitSw.ElapsedTicks;
statFrames++;
ReportStats();
} }
await _pacingDelay(interval, ct); await _pacingDelay(interval, ct);
} }