phase 3: parallel-startup timing trace anchored to camera-event arrival

Adds per-stage timing logs to both the stream and snapshot paths,
all relative to a single t=0 anchor: the moment the camera event
arrived in handleCameraEvent. Lets us see whether snapshot and
stream actually start in parallel (they should, within ~2ms) and
where wall-clock goes inside each path.

handleCameraEvent now captures tEvent = Date.now() and threads it
into startStream(v, tEvent). startStream threads it further into
pushSnapshot(v, cam, tEvent). Both helpers define a `since()` arrow
that computes the current offset.

New log lines on wake:

  event MotionSensor -> "kitchen": fired at +0ms (wake)
  stream "kitchen": start +0ms
  stream "kitchen": socket connect requested +1ms
  snapshot "kitchen": start +1ms
  snapshot "kitchen": takePicture +320ms
  stream "kitchen": socket connect open +24ms
  snapshot "kitchen": transform +458ms via sharp (217KB)
  snapshot "kitchen": post sent +459ms
  snapshot "kitchen": post acked +551ms ← first user-visible paint
  stream "kitchen": first ffmpeg frame +780ms (jpeg=210KB)
  stream "kitchen": first socket.write +781ms

post_acked is the snapshot's true glass-to-glass: /frame returns
after display_flip_back_buffer, so by the time the response
resolves the firmware has the new pixels queued for the next DPI
scanout. No separate firmware-side wiring needed for the snapshot
path's g2g measurement.

The stream path's true g2g still needs the 16-byte header
extension in Phase 4 — `first socket.write` is just "Scrypted sent
the bytes," not "panel showed them."

1 files changed, 36 insertions, 15 deletions

diff --git a/scrypted/scrypted-viewport.ts b/scrypted/scrypted-viewport.ts
index 2cc2bb6..80a36ea 100644
--- a/scrypted/scrypted-viewport.ts
+++ b/scrypted/scrypted-viewport.ts
@@ -6,7 +6,7 @@
 // short git hash of the commit that added this constant — if the
 // hash in the log doesn't match the HEAD this file came from, the
 // Scrypted Script editor is still on stale code.
-const SCRIPT_VERSION = "4d5fd28";
+const SCRIPT_VERSION = "pending";
 //
 // Architecture
 // ------------
@@ -607,19 +607,27 @@ class ScryptedViewportProvider extends ScryptedDeviceBase
             if (detections.some((d: any) => d?.className === "person")) trigger = true;
         }
         if (!trigger) return;
-        this.console.log(`event ${iface} -> "${v.name}": wake`);
+        // Capture the wall-clock at event arrival so every downstream
+        // log line can rebase onto it (+Xms since event). This is the
+        // anchor for measuring glass-to-glass and confirming that
+        // snapshot + stream start truly in parallel.
+        const tEvent = Date.now();
+        this.console.log(`event ${iface} -> "${v.name}": fired at +0ms (wake)`);
         // If a stream is already in flight for this viewport, the event
         // is just reinforcement — the existing ffmpeg child is already
         // pushing frames. We do NOT relaunch (would race with previous).
         if (this.streams.has(v.name)) return;
         if (this.streamStarting.has(v.nativeId!)) return;
         this.streamStarting.add(v.nativeId!);
-        this.startStream(v)
+        this.startStream(v, tEvent)
             .catch(e => this.console.error("startStream failed", e))
             .finally(() => this.streamStarting.delete(v.nativeId!));
     }
 
-    async startStream(v: Viewport) {
+    async startStream(v: Viewport, tEvent: number = Date.now()) {
+        const since = () => Date.now() - tEvent;
+        this.console.log(`stream "${v.name}": start +${since()}ms`);
+
         // Race rule: cancel pending operations on every callback before
         // beginning a fresh stream.
         this.stopStream(v.name, /*sendSleep=*/ false);
@@ -643,7 +651,7 @@ class ScryptedViewportProvider extends ScryptedDeviceBase
         // just overpaints stale data on top of a fresher frame for
         // ~1 paint cycle. Errors are silent so a missing snapshot path
         // doesn't break the stream start.
-        this.pushSnapshot(v, cam).catch(() => {});
+        this.pushSnapshot(v, cam, tEvent).catch(() => {});
 
         // Fetch the panel's native dimensions from the firmware and
         // cache them on the viewport's storage. Falls back to 800x480
@@ -782,6 +790,7 @@ class ScryptedViewportProvider extends ScryptedDeviceBase
             if (abort.signal.aborted) return;
             socketReady = false;
             socketBackpressured = false;
+            this.console.log(`stream "${v.name}": socket connect requested +${since()}ms`);
             sock = net.createConnection({
                 host:    v.host,
                 port:    81,
@@ -789,7 +798,7 @@ class ScryptedViewportProvider extends ScryptedDeviceBase
             });
             sock.on("connect", () => {
                 socketReady = true;
-                this.console.log(`stream "${v.name}": tcp/81 open`);
+                this.console.log(`stream "${v.name}": socket connect open +${since()}ms`);
             });
             sock.on("drain", () => { socketBackpressured = false; });
             sock.on("error", (e: Error) => {
@@ -845,6 +854,8 @@ class ScryptedViewportProvider extends ScryptedDeviceBase
             ]);
             currentProc = p;
 
+            let firstFfmpegFrameLogged = false;
+            let firstSocketWriteLogged = false;
             p.stdout.on("data", (chunk: Buffer) => {
                 if (abort.signal.aborted) return;
                 workBuf = workBuf.length === 0 ? chunk : Buffer.concat([workBuf, chunk]);
@@ -855,6 +866,11 @@ class ScryptedViewportProvider extends ScryptedDeviceBase
                     workBuf = workBuf.subarray(eoi + 2);
                     if (frame.length < 4 || frame[0] !== 0xff || frame[1] !== 0xd8) continue;
 
+                    if (!firstFfmpegFrameLogged) {
+                        this.console.log(`stream "${v.name}": first ffmpeg frame +${since()}ms (jpeg=${(frame.length / 1024).toFixed(0)}KB)`);
+                        firstFfmpegFrameLogged = true;
+                    }
+
                     // Drop only when the socket isn't connected yet
                     // (initial-open race) — once it's up we just keep
                     // writing. Node buffers internally if the kernel
@@ -876,6 +892,10 @@ class ScryptedViewportProvider extends ScryptedDeviceBase
                     // and body across two TCP packets — the firmware
                     // sees them as one contiguous segment when possible.
                     const ok = sock.write(Buffer.concat([header, frame]));
+                    if (!firstSocketWriteLogged) {
+                        this.console.log(`stream "${v.name}": first socket.write +${since()}ms (jpeg=${(frame.length / 1024).toFixed(0)}KB)`);
+                        firstSocketWriteLogged = true;
+                    }
                     writeLatencies.push(Date.now() - t0);
                     if (writeLatencies.length > 200) writeLatencies.shift();
                     bytesSent += 8 + frame.length;
@@ -992,8 +1012,9 @@ class ScryptedViewportProvider extends ScryptedDeviceBase
     //                use it for landscape (no rotate needed).
     //   3. ffmpeg one-shot — old slow path, ~500-700ms cold start.
     //                Always works; the safety net.
-    private async pushSnapshot(v: Viewport, cam: any) {
-        const t0 = Date.now();
+    private async pushSnapshot(v: Viewport, cam: any, tEvent: number = Date.now()) {
+        const since = () => Date.now() - tEvent;
+        this.console.log(`snapshot "${v.name}": start +${since()}ms`);
         let mo: any;
         try { mo = await cam.takePicture({ reason: "event" }); }
         catch (e) { return; }                 // camera doesn't support snapshots
@@ -1001,7 +1022,7 @@ class ScryptedViewportProvider extends ScryptedDeviceBase
 
         const srcJpeg: Buffer = await mediaManager.convertMediaObjectToBuffer(mo, "image/jpeg");
         if (!srcJpeg || srcJpeg.length < 4) return;
-        const tDecoded = Date.now();
+        this.console.log(`snapshot "${v.name}": takePicture +${since()}ms`);
 
         // Cached dims from prior /state read; falls back to 800x480.
         const panelW = parseInt(v.storage.getItem("panel_w") || "0", 10) || 800;
@@ -1068,9 +1089,10 @@ class ScryptedViewportProvider extends ScryptedDeviceBase
         }
 
         if (transformed.length < 4) return;
-        const tTransformed = Date.now();
+        this.console.log(`snapshot "${v.name}": transform +${since()}ms via ${path} (${(transformed.length / 1024).toFixed(0)}KB)`);
 
         try {
+            this.console.log(`snapshot "${v.name}": post sent +${since()}ms`);
             const res = await fetch(`http://${v.host}/frame`, {
                 method: "POST",
                 headers: { "Content-Type": "image/jpeg" },
@@ -1078,11 +1100,10 @@ class ScryptedViewportProvider extends ScryptedDeviceBase
                 signal: AbortSignal.timeout(2000),
             });
             await res.text().catch(() => "");
-            const tPosted   = Date.now();
-            this.console.log(
-                `snapshot "${v.name}" via ${path}: ${tPosted - t0}ms total ` +
-                `(takePicture=${tDecoded - t0}ms transform=${tTransformed - tDecoded}ms ` +
-                `post=${tPosted - tTransformed}ms, ${(transformed.length / 1024).toFixed(0)}KB)`);
+            // post_acked is the snapshot's true glass-to-glass — /frame
+            // returns after display_flip_back_buffer, so the firmware
+            // has the new pixels queued for the DPI scanout by then.
+            this.console.log(`snapshot "${v.name}": post acked +${since()}ms ← first user-visible paint`);
         } catch { /* stream is starting anyway */ }
     }