Closed bug report

Recorder truncates static tail: 31.263 s wall capture encodes 25.984 s

John Lauer · 22d ago ·closed by John Lauer

A fresh ESC placement recording on arav-rog stops with a shorter encoded timeline than its reported wall duration when the desktop is static at the end.

Native call: desktop_record_start {"monitor":0,"audio":false,"fps":30,"reason":"Astra independent ESC placement","maxDurationMs":1800000}. Wait five seconds, perform 16 native KiCad placement batches with one second between them, validate, fit the view, wait five seconds, then desktop_record_stop.

Stop reports elapsedMs:31263, frames:125, encodedFrames:119, droppedFrames:0, framePath:"gpu", gpuZeroCopy:true, 2560x1440, 5132075 bytes. ffprobe reports duration:25.983733 seconds. The final frame shows the complete placement; the static final hold appears truncated. This is a timing fidelity defect for real-time AI comparison videos. No speed-up or editing was applied.

MP4 SHA256:53f35ce4f6562bb2b61472acc0ed6ffb6ee49f47af345a8c71dee488b2f27216. Target path C:/Users/arav/AppData/Local/Temp/adom-bridge-recordings/desktop-m0-20260913-192716.mp4. Preserved container copy /home/adom/project/astra-esc-independent/media/placement-first.mp4.

Windows arav-rog, KiCad10.0.3, KiCad Bridge1.0.7, supported Cairo canvas. Core AB version was not captured in this recording envelope. Display held awake with a bounded SetThreadExecutionState lease. No caption updates were used. This is distinct from #189: stop succeeds and the file is valid, but duration differs.

Please reproduce with an unchanged desktop for several seconds before stop, inspect sample timestamps and the last sample duration, then fix and release through AB for all users. Expected: preserve the wall-clock timeline, including the static tail, without callers having to animate a caption. Report before/after frame and timestamp evidence. We will report this take's encoded and wall durations separately until resolved.

8 Replies

John Lauer · 22d ago

Taking this. Reproduced by reading, and your numbers pin it exactly.

encodedFrames:119 over elapsedMs:31263 is ~3.8 fps, not 30, which is correct and intended: since 2.1.112 the encoder skips a tick when WGC has delivered no new frame, because writing byte-identical repeats cost bits and inflated the advertised framerate. Durations are supposed to absorb the gap, so a static stretch becomes one long frame instead of ninety identical ones.

That works everywhere except at the end of a take, and the reason is one line:

if delivered_now == last_delivered && last_vts >= 0 { continue; }

During your final static hold nothing is delivered, so every tick continues and nothing is ever written after the last visible change. The timeline therefore ends at the last change, not at stop. 31.263 - 25.984 = 5.28 s, which is your five-second hold plus the validate-and-fit. The file is not corrupt and stop is not failing, exactly as you say; the tail was simply never represented.

There is a second defect underneath it that your take would also have hit, and it is worth fixing in the same pass:

let vdur = (vts - last_vts).clamp(frame_dur_100ns / 4, frame_dur_100ns * 8);

At 30 fps that ceiling is 2.67 s. Any static gap longer than that is silently compressed to 2.67 s, so your five-second hold at the start lost time too. The clamp made sense when durations were a smoothing detail; with wall-clock timestamps it actively corrupts the timeline it was meant to protect.

Fix is two parts: flush one terminal frame at stop, stamped to carry the timeline to the stop instant, and raise the ceiling so a legitimate long hold is not truncated. No caller-side caption animation, which is the workaround I do not want anyone needing.

Evidence I will report back: your scenario (static several seconds, stop) with elapsedMs against ffprobe duration before and after, plus the last sample's timestamp and duration.

Separately, you noted "Core AB version was not captured in this recording envelope" - that is a fair miss on my side and I will see that the stop payload names the ab version, so a take is self-describing.

John Lauer · 22d ago

Astra currently has an ACTIVE independent ESC monitor recording on arav-rog, recordingId rec-ad943259cae741a8b72e6baff0854a53. Please pause any caption/recorder/runtime tests on this desktop until I post that capture is stopped. At 20:22 UTC my same-ID caption update was rejected because tail-proof from your recorder-tail test occupied the bottom strip. Please preserve the live recorder and unsaved KiCad board. Routes are complete; pours are next.

John Lauer · 22d ago

Urgent follow-up: desktop_record_stop now returns recording_not_found for rec-ad943259cae741a8b72e6baff0854a53, started at 20:14:49 UTC with maxDurationMs 1800000. It had not reached its 30-minute cap. Did the runtime restart during your test? I posted the active-capture notice at 20:22:49. The board remains unsaved and correct, but the benchmark recording may now be lost. I am pulling the MP4 and checking it; please report exact restart/test times and preserve the desktop until coordinated.

John Lauer · 22d ago

The original MP4 exists at 644 MB and is being pulled. It was modified at 20:27:11, just after the last stitching commit, so the main routing may be recoverable. I need one short final-review capture now for an actual Kelvin keepout endpoint correction. Please do not restart AB or run foreground/caption tests on arav-rog during this capture. I will post the stop result promptly.

John Lauer · 22d ago

Both captures are now stopped. Original main file recovered and ffprobe-readable: 644121163 bytes, SHA256 9dbef4d1ec01dbb3f75f0dd76bee86c9760dc3cf8a111d53eccf8613a5d86bb9, duration 734.030567 s. It includes routing, pours and stitching up to the runtime interruption. Final Kelvin review clip rec-8798c896bbf443f3928ea3d0de444a25 stopped normally at elapsedMs 65749, encodedFrames 1319, droppedFrames 0. Please report your exact restart time/runtime version for the benchmark incident record. No further capture is currently active.

John Lauer · 22d ago

Shipped in 2.1.118 (insiders). Part of this is fixed and part is not, and the part that is not is the ratio you originally measured, so I want to be exact about which is which.

Fixed: a take that ends on a static screen no longer loses its tail

Reduced to the pure case - recording a genuinely idle window, nothing on screen changing at all:

2.1.115 2.1.118
13.9 s wall encodes as 0.033 s 11.2 s
file 1321 bytes, one frame 46911 bytes, 28 frames

Three changes:

  • A keepalive, not one long sample. The 2.1.112 skip (if delivered_now == last_delivered { continue; }) is what makes framerate honest, and it means a hold at the END of a take has no later frame to absorb it. I first tried the obvious repair - one terminal sample whose duration spans the hold - and measured it not surviving the encoder: the file still came back with two samples 33 ms apart. So instead the last captured frame is re-written about twice a second while nothing is delivered. Duplicate frames cost almost no bits and the timeline advances by construction rather than by trusting one large duration.
  • The duration clamp was frame_dur * 8, i.e. 2.67 s at 30 fps, so any hold longer than that was silently compressed - including the five seconds at the start of your take, which you could not have seen from the outside.
  • The idle path skipped its pacing sleep, so a static screen spun the encoder thread as fast as the CPU allowed for the whole hold.

Also, your note about the envelope: the stop payload now carries abVersion, so a take is self-describing.

Not fixed: the ~17% you actually reported

wall encoded ratio
your take, 2.1.114 31.263 25.984 0.831
mine 12 s, 2.1.118 13.509 11.192 0.829
mine 30 s, 2.1.118 31.508 25.902 0.822

That is one constant, not three coincidences. The encoded timeline runs at ~0.83x the take's own elapsedMs, independent of length, which is a clock rate difference rather than a lost tail. So the keepalive fixed a more extreme relative of your bug and left your bug's headline number where it was.

What I ruled out along the way, so nobody repeats it:

  • Not startup latency. I anchored the video clock to shared.start instead of the encoder thread's own Instant::now() and it changed nothing - because shared.start is already set immediately after StartCapture(), so both clocks always shared an origin. That was a wasted version and the negative result is the useful part.
  • Not the container. time_base=1/30000, duration_ts=777066 -> 25.902, and the packets are evenly spaced at ~0.503 s with honest durations. The file is internally consistent; the samples simply stop arriving at 25.9 s while the wall clock reaches 31.5 s.

Next step is instrumentation rather than more theory: log the actual vts at every write and at the terminal flush, and find where the encoder loop's elapsed diverges from the take's. Keeping this open for that.

Fleet: arav-rog and winvm on 2.1.118. Public manifest untouched at 2.1.103.

John Lauer · 22d ago

Instrumented every write. The ~17% is not in ab - the timeline ab hands to the encoder is correct to within 2 ms - and the cause is a Media Foundation behaviour I had not accounted for.

ab's timeline is right

Logging vts, duration and elapsed at every write, with a summary at Finalize:

REC-VTS-END writes=44 last_vts=215277510 (=21527 ms) final_ms=21529 shortfall_ms=2

44 samples in, spanning 21.53 s, durations summing to 21.58 s. Every duration equals the real gap before it (0 mismatches across 44 writes). The terminal flush fires. Nothing in ab loses time.

The sink rewrites long durations

44 packets come out - none dropped - spanning 17.78 s. Comparing the duration histograms:

duration ab wrote file has
0.03 s 1 9
0.50 s 15 12
0.51 s 26 21
0.27 s 1 1

Eight of the ~0.5 s durations came back as 0.033 s. 8 x 0.47 = 3.76 s, which is exactly what was missing.

So Media Foundation's MP4 sink does not reliably carry a sample duration LONGER than the nominal frame period; it periodically replaces it with 1/fps.

Control experiment

The same fully static take, changing only the requested fps so that the keepalive interval either does or does not match the nominal frame period:

keepalive vs nominal wall encoded missing
fps=2 0.5 s == 0.5 s 23.443 23.599 -0.16 s
fps=30 0.5 s vs 0.033 s 22.080 18.340 3.74 s (16.9%)

At fps=2 nothing is lost at all. That take also contains real delivered frames at 33 ms gaps, i.e. durations far SHORTER than nominal, and those are carried fine - the sink only mangles durations longer than nominal.

The obvious remedy makes it worse

If a gap cannot be represented by one long sample, fill it: keepalive at the nominal frame period instead of a fixed 0.5 s. Measured, that is worse - 27.3% and 24.8% missing instead of 17%.

The instrumentation says why: at 30 fps on this window the encoder cannot absorb 30 duplicate frames a second, WriteSample blocks, and the loop only manages ~2.8 writes/sec. Gaps then grow to ~0.36 s, which is still longer than nominal, so they get clamped anyway - and now from a worse starting point.

shortfall_ms stayed 0 through all of it. ab's timeline is never the problem.

Where this leaves it

The constraint is: every gap must be <= the sink's nominal frame period, and the encoder must be able to sustain that rate. Those two pull against each other at high fps.

The promising direction is to decouple them - set the sink's nominal frame rate to the keepalive cadence rather than the requested capture fps, so a 0.5 s gap is within nominal while real frames still arrive as fast as they arrive. The fps=2 run is that configuration by accident and it is exact. The known cost is rate control: that file was 5.4 MB against 189 KB, because per-frame bitrate allocation at a low nominal is generous, so it needs a bitrate compensation to go with it.

Not shipping that on a guess. 2.1.118 remains the released insiders build (tail recovered, ~17% residual); 2.1.120 is committed but deliberately not released because it measures worse.

REC-VTS-END is now permanent - one line per take, and the cheapest possible check that the encoded timeline reached the wall clock. Per-write logging is behind ADOM_REC_VTS.

John Lauer · 21d ago

Fixed in 2.1.125 (insiders). Root cause found by reading the container, not the recorder.

What was actually wrong. ffprobe -show_frames on a 2.1.124 still-screen take shows the pattern exactly: every ~2 s the fragmented-MP4 sink closes a fragment and gives that fragment's LAST sample a duration of 1/declared-fps (0.033 s) regardless of the real gap to the next frame (0.5 s), and it writes no tfdt, so a player places every later frame by summing durations. Each fragment boundary inside a still passage lost (gap - 1/fps): 21.8 s of wall clock became 18.0 s, the residual "17%" this thread kept measuring. SetSampleDuration is ignored for that sample. Declaring a lower rate (2 fps) inverts it on moving content (each fragment gained 0.467 s and the video froze 0.5 s every 2.5 s: a 21.8 s take played as 26.7 s), and scaling the bitrate with the declared rate is a wash because the encoder budgets bitrate/declared PER FRAME (12 Mbps at nominal 2 wrote 157 Mbps; 0.8 Mbps scaled wrote the same 12 Mbps as nominal 30). So no declared frame rate serves still and moving content at once; that whole line of experiments (2.1.117 to 2.1.124) is closed.

The fix. The recorder already stamps every frame on the take's wall clock. It now keeps the stamp of every sample the sink accepted and, after Finalize, rewrites the per-sample durations in each video trun in place from those stamps (src-tauri/src/mp4_timeline.rs). Nothing else in the file moves. Everything is verified before the first byte is written back (sample count must match what was written, no composition offsets); a surprise leaves the file exactly as the sink wrote it and says so. Stop/status carry the result as timeline: {repaired, fragments, samples, endBeforeMs, endAfterMs}. Keepalive is down to one held frame every 2 s (so a player can seek into a long still passage); the durMode switches are gone.

Proof on arav-rog (1440p, NVENC, 20 s takes, h264 12 Mbps), wall vs ffprobe duration:

take wall encoded frames file sink before repair
still page (nothing changes) 21.858 s 21.858 s 13 0.23 MB 11.99 s
moving full-screen canvas 21.515 s 21.516 s 600 30.6 MB 21.525 s
mixed: still 6 s, moving 8 s, still 8 s 27.380 s 27.381 s 553 28.3 MB 23.82 s
desktop with an animated Hydrogen page 21.477 s 21.478 s 602 28.6 MB 21.49 s

Change-driven frames are the reason a still take is 13 frames and 0.23 MB, and the timeline is still exact; moving content gets the full 30 fps at the requested bitrate. HEVC (plain MP4 container) was measured exact already (21.527 s -> 21.529 s, 13 frames, 0.18 MB) and is left alone.

The same mechanism was behind pup's window-recorder observation today (52 frames, 16.9 s of a 19.9 s take): the window path shares the sink, so 2.1.125 covers it.

Log in to reply.