Fix closed-loop latency instrumentation and two live-mode freezes

[MarkSant]

Why

Optical validation of the DRerio sessions showed the software log understating physical latency by 2.8x (411 ms real vs 148 ms logged), and the declared fps (30) not matching the real one (38.95). A statistical audit of latency_log.csv showed it was an instrumentation artefact, not a measurement:

• 346/354 rows with a sub-millisecond serial round trip — physically impossible at 9600 baud
• the end-to-end column near-uniform over exactly one frame interval
• a negative correlation between the serial leg and the total

Both causes were confirmed in code. While validating the fix on the rig, two separate freezes surfaced and are fixed here too.

Instrumentation fixes

Stale ACK	reset_input_buffer() ran after readline(), so from the second trigger on, readline returned the previous command's ACK, already sitting in the buffer. Root cause of the 346 impossible rows. Now drained before the write.
Wrong frame	The module-level FRAME_T0 was set by the reader thread on every cap.read(), including frames never consumed — get_frame() returns only the most recent. It pointed at a frame later than the one that produced the decision. Global removed; the capture timestamp travels with the frame.
Every ACK a nack	if response == "OK" never matched — the firmware replies "Red LED 1 ON". Every command was logged as a nack and send_command returned False despite the LED firing. Any non-empty reply is now an ACK.
False fps	VideoWriter was stamped with the configured fps on a ~39 fps stream. It now takes the measured rate.
Unrecoverable frame index	Neither live_frame_count nor the mp4 index is a camera frame index — frames are skipped at get_frame() and dropped again at both queues. Added a frame ledger; drops are counted instead of silent.

latency_logging.py is rewritten and writes three files per session into the recording folder: 6_Latency_<base>.csv (schema compatible with the DRerio unit), 7_FrameLedger_<base>.csv, 8_LatencyMeta_<base>.json.

Freezes found on the rig

1. Live preview via HighGUI on a worker thread. cv2.imshow/waitKey/destroyAllWindows ran on the processing thread while Tk owned the main thread. HighGUI drives a Win32 message loop belonging to the calling thread; with Tk running its own (modal dialogs included), the two can attach and waitKey never returns. Preview now renders through Tk via root.after, throttled to 20 fps and downscaled to 800 px on the worker, dropping frames rather than blocking.

2. Unbounded serial write. connect() set timeout=0.25 but left write_timeout at pyserial's default of None — on Windows that is WriteFile + GetOverlappedResult(bWait=True), a wait with no bound. One stalled write froze the analysis thread for 60 s, until the port was closed. The session log made it unambiguous:

13:40:40.834  threads.join.timeout  thread=processing_thread
13:40:49.383  threads.join.finished
13:40:49.384  arduino.command.sent  command=7     <- logged right after ser.write()
13:40:49.384  arduino.connection.closed

write_timeout is now set and SerialTimeoutException is reported as a lost trigger. Beyond that, serial I/O moved off the analysis thread entirely: send_command_async() queues (maxsize 8) and a dedicated ArduinoTxThread writes. A stalled port now costs counted, logged trigger drops instead of a frozen application. t_send/t_ack are still taken around the real write, so the latency columns keep their meaning; the queue hop shows up in decision_to_send_ms, where it is visible rather than hidden.

Hardening so a stall can never freeze everything again: all joins in join_threads() bounded at 5 s and naming the offending thread; both live loops log exceptions instead of dying silently; Camera.release() no longer calls cap.release() while the reader is still inside cap.read(); get_properties() no longer queries the capture backend from another thread; a camera.read.stalled warning fires on reads over 2 s.

Deliberately not changed

CAP_PROP_BUFFERSIZE and the free-running reader thread. Prediction: this unit will measure much lower camera delay than the DRerio one (which measured 102.6 ms ≈ exactly 4.0 frame intervals, typical of a DirectShow buffer) because its reader drains the buffer while DRerio's sleeps between reads. That is a real architectural difference between two published systems — it should be measured, not normalised away beforehand.

Verification

• ruff check src tests clean
• 44 tests pass, including 10 new ones whose FakeSerial models the stale-buffer ordering. Three of them fail when the old ACK ordering is restored — verified regression coverage.
• Async dispatch tested against a permanently wedged port: 20 triggers enqueued in 0.97 ms with the caller never blocking, surplus dropped and logged, close() returning in 1 s.

Not verified: no live hardware run since the last fix. The freeze diagnosis comes from the session log plus the code, not from a reproduction on the rig.

Follow-up, not in this PR

cv2.VideoCapture(1) has taken 35 seconds to open on two consecutive sessions. That is not normal and it is the same device that stalled the serial port afterwards — worth suspecting the USB hub or the camera driver. The new camera.read.stalled warning will show if cap.read() starts stalling too.

[Copilot]

Pull request overview

This PR fixes closed-loop latency instrumentation so logged timing reflects physical reality, and hardens live-mode execution to prevent UI/analysis freezes (moving preview rendering to Tk’s main thread and isolating serial I/O from the analysis thread).

Changes:

• Reworks latency logging to remove the stale global frame timestamp, record per-trigger legs, add a frame ledger, and write session metadata sidecars.
• Moves Arduino trigger dispatch to an async TX thread with bounded write timeouts; updates ACK handling to match real firmware replies.
• Fixes live preview freezes by rendering via Tk (root.after) instead of HighGUI calls on a worker thread; adds stall detection and bounded thread joins.

Reviewed changes

Copilot reviewed 8 out of 8 changed files in this pull request and generated 4 comments.

Show a summary per file

File	Description
tests/test_latency_instrumentation.py	Adds regression tests covering stale-buffer ACK ordering and frame timestamp provenance.
src/zebtrack/ui/gui.py	Carries capture timestamps with frames, logs drops/ledger entries, and renders live preview via Tk main thread.
src/zebtrack/latency_logging.py	Rewritten session logger producing trigger CSV, frame ledger CSV, and metadata JSON with measured fps + drop counts.
src/zebtrack/io/recorder.py	Allows stamping video container fps with measured camera rate and logs the chosen fps.
src/zebtrack/io/camera.py	Adds per-frame capture timestamp/sequence tracking, measured fps reporting, and avoids cross-thread capture property queries.
src/zebtrack/io/arduino.py	Adds async TX dispatch, enforces write_timeout, drains input buffer before write, and fixes ACK acceptance logic.
src/zebtrack/core/detector.py	Publishes decision metadata/timing for latency instrumentation without changing the public return tuple.
src/zebtrack/core/controller.py	Starts/stops latency sessions with recording lifecycle, stamps container fps with measured fps, and bounds thread joins.

Suppressed comments (2)

src/zebtrack/latency_logging.py:193

• log_video_frame also reads _SESSION outside _LOCK, which can race with stop_session in the same way as note_capture. Acquire _LOCK before checking _SESSION so stop_session can reliably quiesce logging before closing files.

    s = _SESSION
    if s is None:
        return None
    try:
        with _LOCK:

src/zebtrack/latency_logging.py:227

• log_trigger reads _SESSION before acquiring _LOCK. If stop_session runs concurrently, this can capture a stale session handle and still write to it even after _SESSION is cleared. Grab _LOCK before reading _SESSION to make session teardown race-free.

    s = _SESSION
    if s is None:
        return
    try:
        with _LOCK:

---

💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.

[MarkSant]

Thanks — three of the four were real. Addressed in d906120.

Session teardown race (latency_logging.py, all four call sites incl. the two suppressed comments). Fixed as suggested: _SESSION is now read under _LOCK everywhere, and stop_session holds the lock across the whole teardown — snapshot, sidecar write and close — rather than clearing the global first and closing the handles afterwards. That second half mattered as much as the read: a call that had already taken the handle could write to a closed file.

Worth recording that this was not theoretical. The new concurrency test, run against the pre-fix code, produces a ledger with 13779 rows while the metadata claims 13777 — the sidecar counters and the CSVs disagreeing is exactly the kind of quiet corruption this module exists to prevent.

Unlogged write timeouts. Agreed, and the contract violation was worse than stated: a trigger the firmware may never have acted on was indistinguishable from one never attempted. In a latency study that is a silently dropped data point. log_trigger now accepts t_ack=None and writes the row with the acknowledgement columns empty and ack_ok false. I also closed the same gap on the path this PR introduced — triggers dropped because the TX queue is full are counted as trigger_queue_drops in the metadata.

0.0 as a legal timestamp. Correct, and it applied to the CSV formatting as well as the arithmetic. perf_counter's epoch is arbitrary, so 0.0 is a reading, not an absence. All timestamp handling now goes through one _fmt helper that is explicit about None.

fps truthiness in recorder.py — declined as proposed, fixed differently. A bare fps is not None check would let fps=0.0 reach VideoWriter and produce a container no player can time. That is worse than the bug it replaces: the truthiness check at least fell back to a usable rate. Written as fps is not None and float(fps) > 0 instead — explicit about None, still rejecting values that cannot be stamped. Note the caller can only ever pass None or a positive float (Camera.measured_fps returns None when the span is non-positive), so this is about being well-defined at the boundary, not about a reachable path.

Three regression tests added, all verified to fail against the pre-review code. Suite is at 47 passing, ruff clean.