diag(build): per-build GUID stamp + resolve/blit timing split (take-6 attribution failure)

Take 6 measured render 35-41ms — WORSE than take 5's 25.5 — and the run could
not be attributed to a binary: exe mtime != build contents (incremental builds
serve stale exes; a source edit without rebuild is a silent old binary). Three
takes of a perf saga had been judged against builds nobody could prove.

- ytLive.csproj GenerateBuildStamp target: fresh GUID per compile (writes
  obj/BuildStamp.g.cs -> Helpers/BuildStamp.Id/BuiltLocal). Deliberately defeats
  incremental lies: every 'dotnet build' recompiles the app project.
- Wordmark shows the id as a superscript (TopBar.xaml, x:Static, 9px grey
  BaselineAlignment=Superscript); startup.log records 'Build <id> (compiled
  <time>)' so every take is cross-readable with the visible UI.
- FramePump stats split the tick: 'avg render Xms (resolve Y), avg submit Z' —
  the resolver is timed separately (wrapper resolver on per-tick paths; bake
  keeps the raw one) so take 7 names the hot half of 'render' with data.
- Fixed a latent transition-clock bug found on the way: lastTick now restarts
  every frame (the branch rework had restarted it only during transitions,
  letting a transition begun after idle complete instantly on its first Tick).

ONE integration test family: BuildStampTests (unit: shape) +
BuildStampDisplayTests (RealApp, namescoped FindName on TopBar proves the
wordmark SHOWS the id). 47/47 per-class green, clean build 0 warnings. Docs
same commit. User's top-bar/session spec (re-sent twice) + settled Q&A
decisions folded into HANDOFF Unit B — next work unit after take 7 verdict.
This commit is contained in:
2026-09-04 11:26:46 -07:00
parent 1c48849853
commit 27bf74389d
8 changed files with 102 additions and 17 deletions
+31 -8
View File
@@ -265,7 +265,11 @@ public sealed class FramePump : IDisposable
// 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;
// Resolve-vs-composite split (2026-09-04, take-6 ambiguity): "render" was a
// 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;
int statFrames = 0;
var statsNext = DateTime.UtcNow + TimeSpan.FromSeconds(5);
void ReportStats()
@@ -275,13 +279,25 @@ public sealed class FramePump : IDisposable
_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 render {renderTicks / (double)System.Diagnostics.Stopwatch.Frequency * 1000 / statFrames:F1}ms " +
$"(resolve {resolveTicks / (double)System.Diagnostics.Stopwatch.Frequency * 1000 / statFrames:F1}), " +
$"avg submit {submitTicks / (double)System.Diagnostics.Stopwatch.Frequency * 1000 / statFrames:F1}ms");
renderTicks = submitTicks = 0;
renderTicks = submitTicks = resolveTicks = 0;
statFrames = 0;
statsNext = DateTime.UtcNow + TimeSpan.FromSeconds(5);
}
// One wrapper shared by every render of the run — resolve time accumulates
// inside the render measurement, and the stats line reports the split.
VideoFrame? TimedResolver(SceneElement element)
{
resolveSw.Restart();
var frame = _frameResolver(element);
resolveSw.Stop();
resolveTicks += resolveSw.ElapsedTicks;
return frame;
}
try
{
while (!ct.IsCancellationRequested)
@@ -312,12 +328,15 @@ public sealed class FramePump : IDisposable
// pooling change because its buffer's only consumer was its own release.
renderSw.Restart();
var scratch = AcquireScratch(scratchSize);
frame = RenderScene(scene, compositorOptions, socialBarFrame, socialBarTop, scratch);
frame = RenderScene(scene, compositorOptions, socialBarFrame, socialBarTop, scratch, TimedResolver);
if (_transition is { Active: true } transition)
{
frame = transition.BlendFrame(frame);
transition.Tick(lastTick.Elapsed.TotalMilliseconds);
}
// Restarted EVERY frame (transition or not) so a transition's first
// Tick sees per-frame time, not the pump's whole uptime.
lastTick.Restart();
// Restarted EVERY frame (transition or not) — the old per-frame reset
// is what stops a transition that begins after idle from inheriting
// a giant ElapsedMs and completing instantly on its first tick.
@@ -394,10 +413,14 @@ public sealed class FramePump : IDisposable
CompositorOptions options,
VideoFrame? socialBarFrame,
int socialBarTop,
byte[]? scratch = null)
byte[]? scratch = null,
Func<SceneElement, VideoFrame?>? resolver = null)
{
// per-tick composites use the (timed) resolver; the rare bake uses the raw one
// so bake cost lands in "render" but not "resolve".
resolver ??= _frameResolver;
if (_sceneGraph == null)
return _compositor.Render(scene, _frameResolver, null, options, socialBarFrame, socialBarTop, scratch: scratch);
return _compositor.Render(scene, resolver, null, options, socialBarFrame, socialBarTop, scratch: scratch);
var split = _sceneGraph.GetSplitPoint(scene);
if (split == scene.Elements.Count)
@@ -412,11 +435,11 @@ public sealed class FramePump : IDisposable
if (baseFrame != null)
{
return SceneCompositor.CompositeLayers(
baseFrame, scene, split, _frameResolver, options, socialBarFrame, socialBarTop, scratch: scratch);
baseFrame, scene, split, resolver, options, socialBarFrame, socialBarTop, scratch: scratch);
}
// No static base (first layer is dynamic or empty scene) — full render.
return _compositor.Render(scene, _frameResolver, null, options, socialBarFrame, socialBarTop, scratch: scratch);
return _compositor.Render(scene, resolver, null, options, socialBarFrame, socialBarTop, scratch: scratch);
}
private void OnProcessFailed(object? sender, string message)