unified end-to-end per-frame instrumentation + version stamps

Cross-side timing was opaque: script saw "req=70ms" but couldn't
split TCP/dispatch overhead from firmware decode time, and firmware
serial logs and Scrypted console logs couldn't be correlated.

Firmware /frame handler now emits Server-Timing on every response
with per-stage breakdown:
  Server-Timing: recv;dur=X, dec;dur=Y, paint;dur=Z,
                 post;dur=W, handle;dur=total
Script parses it, joins by X-Frame-Seq implicitly (one POST per seq),
derives net_up = req − fw_total, and logs a multi-line p50/p95
breakdown every 10 fetches:

  fetch "kitchen" #10 (jpeg=137KB)
     wall      p50=65ms  p95=140ms
     emit→post p50=0ms   p95=2ms      (queue wait)
     req       p50=62ms  p95=135ms    (fetch → Response headers)
       net_up  p50=43ms  p95=110ms    (TCP + body wire + dispatch)
       fw_recv p50=12ms  p95=18ms     (body off the wire)
       fw_dec  p50=6ms   p95=8ms      (hardware JPEG)
       fw_paint p50=0.1ms p95=0.2ms   (backbuffer flip)
       fw_post p50=0.4ms p95=0.6ms
     body-read p50=1ms                 (drain — empty body)
     inflight  d0=8 d1=2 d2=0
     stale-drops=0

Plus version stamps on both sides for the "is the user on the right
code" question:
- CMakeLists: PROJECT_VER = git short hash + -dirty marker if dirty.
  esp_app_get_description()->version exposes it at runtime. Boot
  log: "Scrypted Viewport boot (v0.1.0 build=4cf36e2-dirty)".
- TS: SCRIPT_VERSION const at the top, bumped per commit, logged at
  script-eval: "Scrypted Viewport up (script=4cf36e2). Callback ..."

4 files changed, 124 insertions, 14 deletions

diff --git a/CMakeLists.txt b/CMakeLists.txt
index 5281b89..9ca9c34 100644
--- a/CMakeLists.txt
+++ b/CMakeLists.txt
@@ -1,6 +1,27 @@
 cmake_minimum_required(VERSION 3.16)
 
-set(PROJECT_VER "0.1")
+# Stamp the build with the current git short hash + dirty marker so
+# the firmware can log it at boot and we can verify which commit is
+# running on the device when reading log output. Falls back to
+# "unknown" outside a git checkout.
+execute_process(
+    COMMAND git rev-parse --short HEAD
+    WORKING_DIRECTORY ${CMAKE_SOURCE_DIR}
+    OUTPUT_VARIABLE GIT_HASH
+    OUTPUT_STRIP_TRAILING_WHITESPACE
+    ERROR_QUIET)
+execute_process(
+    COMMAND git diff --quiet HEAD --
+    WORKING_DIRECTORY ${CMAKE_SOURCE_DIR}
+    RESULT_VARIABLE GIT_DIRTY_RC
+    ERROR_QUIET)
+if(NOT GIT_HASH)
+    set(GIT_HASH "unknown")
+endif()
+if(NOT GIT_DIRTY_RC EQUAL 0)
+    set(GIT_HASH "${GIT_HASH}-dirty")
+endif()
+set(PROJECT_VER "${GIT_HASH}")
 set(PROJECT_VER_NUMBER 1)
 
 include($ENV{IDF_PATH}/tools/cmake/project.cmake)
diff --git a/main/app_main.c b/main/app_main.c
index a60496d..00a77bb 100644
--- a/main/app_main.c
+++ b/main/app_main.c
@@ -10,6 +10,7 @@
 #include "touch.h"
 #include "viewport_state.h"
 
+#include "esp_app_desc.h"
 #include "esp_event.h"
 #include "esp_log.h"
 #include "esp_netif.h"
@@ -39,7 +40,12 @@ void app_main(void)
 
     viewport_state_init();
     nvs_config_load();  // apply persisted config over defaults (best-effort)
-    ESP_LOGI(TAG, "Scrypted Viewport boot (v%s)", VIEWPORT_VERSION);
+    // PROJECT_VER comes from CMakeLists.txt — git short hash + dirty
+    // marker. Logged in the very first line so any captured boot log
+    // tells us exactly which build is running.
+    const esp_app_desc_t *desc = esp_app_get_description();
+    ESP_LOGI(TAG, "Scrypted Viewport boot (v%s build=%s)",
+             VIEWPORT_VERSION, desc ? desc->version : "?");
 
     // ------------------------------------------------------------------
     // Networking. Driver starts even with no cable plugged in; we just
diff --git a/main/http_api.c b/main/http_api.c
index c490a85..69e555e 100644
--- a/main/http_api.c
+++ b/main/http_api.c
@@ -499,6 +499,22 @@ static esp_err_t frame_post_handler(httpd_req_t *req)
 
     state_machine_frame_painted();  // reset idle timer
 
+    // Server-Timing per-stage breakdown so the Scrypted side can build
+    // a unified end-to-end trace per frame (joined by X-Frame-Seq).
+    // Units are ms with 0.1ms precision — paint is sub-millisecond
+    // so the decimal matters there. Scrypted subtracts the sum from
+    // its own (fetch_start → Response_headers) measurement to derive
+    // the network up + handler-dispatch overhead it can't see directly.
+    char st_hdr[160];
+    snprintf(st_hdr, sizeof(st_hdr),
+             "recv;dur=%.1f, dec;dur=%.1f, paint;dur=%.1f, post;dur=%.1f, handle;dur=%.1f",
+             (t_recv   - t_first_byte) / 1000.0,
+             (t_decode - t_recv)       / 1000.0,
+             (t_paint  - t_decode)     / 1000.0,
+             (t_post   - t_paint)      / 1000.0,
+             (t_post   - t_entry)      / 1000.0);
+    httpd_resp_set_hdr(req, "Server-Timing", st_hdr);
+
     httpd_resp_set_status(req, "204 No Content");
     return httpd_resp_send(req, NULL, 0);
 }
diff --git a/scrypted/scrypted-viewport.ts b/scrypted/scrypted-viewport.ts
index 0c78578..c13d8a1 100644
--- a/scrypted/scrypted-viewport.ts
+++ b/scrypted/scrypted-viewport.ts
@@ -1,5 +1,13 @@
 // Scrypted Viewport — v1 Scripts-plugin script
 //
+// SCRIPT_VERSION is bumped on every commit that touches this file.
+// The boot log emits it so we can verify the user re-pasted the
+// latest version when reading the plugin console. Format is the
+// 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 = "pending";
+//
 // Architecture
 // ------------
 // One parent device (DeviceProvider + DeviceCreator + HttpRequestHandler)
@@ -353,7 +361,7 @@ class ScryptedViewportProvider extends ScryptedDeviceBase
         // omitted nativeId falls back to the plugin's own endpoint.
         const raw = await endpointManager.getInsecurePublicLocalEndpoint(this.nativeId);
         this.scryptedBase = raw.replace(/\/$/, "");
-        this.console.log(`Scrypted Viewport up. Callback URL base: ${this.scryptedBase}`);
+        this.console.log(`Scrypted Viewport up (script=${SCRIPT_VERSION}). Callback URL base: ${this.scryptedBase}`);
 
         // Re-discover every known child so Scrypted reattaches its storage
         // to the nativeId. Without this, `new Viewport(...)` instantiates
@@ -918,21 +926,59 @@ class ScryptedViewportProvider extends ScryptedDeviceBase
     // X-Frame-Drop responses from the firmware.
     private fetchCount = new Map<string, number>();
     private fetchSamples = new Map<string, {
-        emit: number[]; req: number[]; bread: number[]; wall: number[];
-        depths: { d0: number; d1: number; d2: number };
+        // Script-side wall-clock spans, ms.
+        emit:    number[];   // ffmpeg emit → fetch() call
+        wall:    number[];   // emit → fetch resolved (end-to-end)
+        req:     number[];   // fetch() → Response headers
+        bread:   number[];   // Response → body drained
+        // Firmware-side spans from Server-Timing (already ms).
+        fw_recv: number[];   // body bytes off the wire
+        fw_dec:  number[];   // hardware JPEG decode
+        fw_paint:number[];   // back buffer flip
+        fw_post: number[];   // state counters + unlock + resp headers
+        fw_tot:  number[];   // firmware total (recv + dec + paint + post)
+        // Derived: time fetch() spent in flight that firmware DIDN'T
+        // see. net_up = req - fw_tot ≈ TCP setup + body wire time
+        // + httpd dispatch.
+        net_up:  number[];
+        depths:  { d0: number; d1: number; d2: number };
         staleDrops: number;
     }>();
 
     private bucketsFor(nid: string) {
         let s = this.fetchSamples.get(nid);
         if (!s) {
-            s = { emit: [], req: [], bread: [], wall: [],
+            s = { emit: [], wall: [], req: [], bread: [],
+                  fw_recv: [], fw_dec: [], fw_paint: [], fw_post: [], fw_tot: [],
+                  net_up: [],
                   depths: { d0: 0, d1: 0, d2: 0 }, staleDrops: 0 };
             this.fetchSamples.set(nid, s);
         }
         return s;
     }
 
+    // Parse a Server-Timing header like
+    //   recv;dur=12.3, dec;dur=4.5, paint;dur=0.1, post;dur=0.2, handle;dur=17.1
+    // into a record of name→duration_ms. Robust to whitespace and
+    // missing entries; returns {} on malformed input.
+    private parseServerTiming(h: string | null): Record<string, number> {
+        const out: Record<string, number> = {};
+        if (!h) return out;
+        for (const tok of h.split(",")) {
+            const parts = tok.trim().split(";");
+            const name  = parts[0]?.trim();
+            if (!name) continue;
+            for (let i = 1; i < parts.length; i++) {
+                const [k, v] = parts[i].trim().split("=");
+                if (k === "dur") {
+                    const n = Number(v);
+                    if (Number.isFinite(n)) out[name] = n;
+                }
+            }
+        }
+        return out;
+    }
+
     // First-paint fast path. takePicture → quick ffmpeg one-shot to
     // transpose+scale to panel-native dims → POST /frame. Shares the
     // viewport's frameSeq counter so a slow snapshot can't paint over
@@ -1029,6 +1075,7 @@ class ScryptedViewportProvider extends ScryptedDeviceBase
         const res = await fetch(`http://${v.host}/frame`, opts);
         const tHeaders = Date.now();
         const wasStale = res.headers.get("X-Frame-Drop") === "stale-seq";
+        const fwTiming = this.parseServerTiming(res.headers.get("Server-Timing"));
         // Drain body so the socket can be released back to the pool.
         // Body is empty for 200/204/409; reading is essentially free
         // but the await pins our body-read measurement.
@@ -1036,10 +1083,22 @@ class ScryptedViewportProvider extends ScryptedDeviceBase
         const tDone = Date.now();
 
         const b = this.bucketsFor(v.nativeId!);
+        const req_ms  = tHeaders - tFetchStart;
+        const fw_tot  = fwTiming.handle ?? 0;
         b.emit.push (tFetchStart - emitMs);
-        b.req.push  (tHeaders    - tFetchStart);
+        b.req.push  (req_ms);
         b.bread.push(tDone       - tHeaders);
         b.wall.push (tDone       - emitMs);
+        if (fwTiming.recv  != null) b.fw_recv.push(fwTiming.recv);
+        if (fwTiming.dec   != null) b.fw_dec.push(fwTiming.dec);
+        if (fwTiming.paint != null) b.fw_paint.push(fwTiming.paint);
+        if (fwTiming.post  != null) b.fw_post.push(fwTiming.post);
+        if (fw_tot         >  0)    b.fw_tot.push(fw_tot);
+        // net_up = the slice of req that the firmware DIDN'T see —
+        // TCP handshake (when no keep-alive), body bytes on the wire,
+        // and httpd dispatch from socket-readable to handler entry.
+        // Can go slightly negative under clock skew; clamp at 0.
+        if (fw_tot > 0) b.net_up.push(Math.max(0, req_ms - fw_tot));
         if (depthAtQueue === 0) b.depths.d0++;
         else if (depthAtQueue === 1) b.depths.d1++;
         else b.depths.d2++;
@@ -1053,14 +1112,22 @@ class ScryptedViewportProvider extends ScryptedDeviceBase
                 const sorted = arr.slice().sort((a, b) => a - b);
                 return sorted[Math.min(sorted.length - 1, Math.floor(sorted.length * q))];
             };
+            const fmt = (arr: number[]) => arr.length
+                ? `p50=${p(arr, 0.5).toFixed(1)}ms p95=${p(arr, 0.95).toFixed(1)}ms`
+                : `(no data)`;
             this.console.log(
-                `fetch "${v.name}" #${n} (jpeg=${(jpeg.length / 1024).toFixed(0)}KB) ` +
-                `wall p50=${p(b.wall, 0.5)}ms p95=${p(b.wall, 0.95)}ms | ` +
-                `emit→post p50=${p(b.emit, 0.5)}ms p95=${p(b.emit, 0.95)}ms | ` +
-                `req p50=${p(b.req, 0.5)}ms p95=${p(b.req, 0.95)}ms | ` +
-                `body-read p50=${p(b.bread, 0.5)}ms | ` +
-                `inflight d0=${b.depths.d0} d1=${b.depths.d1} d2=${b.depths.d2} | ` +
-                `stale-drops=${b.staleDrops}`);
+                `fetch "${v.name}" #${n} (jpeg=${(jpeg.length / 1024).toFixed(0)}KB)\n` +
+                `   wall      ${fmt(b.wall)}\n` +
+                `   emit→post ${fmt(b.emit)}   (queue wait before fetch() called)\n` +
+                `   req       ${fmt(b.req)}   (fetch start → Response headers)\n` +
+                `     net_up  ${fmt(b.net_up)}   (req − fw_total: TCP setup + body wire + dispatch)\n` +
+                `     fw_recv ${fmt(b.fw_recv)}   (firmware body read off the wire)\n` +
+                `     fw_dec  ${fmt(b.fw_dec)}   (hardware JPEG → BGR888)\n` +
+                `     fw_paint${fmt(b.fw_paint)}   (backbuffer flip)\n` +
+                `     fw_post ${fmt(b.fw_post)}   (state counters + unlock)\n` +
+                `   body-read ${fmt(b.bread)}   (Response → drained)\n` +
+                `   inflight  d0=${b.depths.d0} d1=${b.depths.d1} d2=${b.depths.d2}   (queue depth at fetch start)\n` +
+                `   stale-drops=${b.staleDrops}`);
             this.fetchSamples.delete(v.nativeId!);   // reset window
         }
         if (res.status === 409) {