instrumentation: firmware idle gap between frames + Scrypted per-fetch wall-clock

2 files changed, 34 insertions, 5 deletions

diff --git a/main/http_api.c b/main/http_api.c
index 447cb52..28ceeeb 100644
--- a/main/http_api.c
+++ b/main/http_api.c
@@ -312,6 +312,11 @@ static esp_err_t respond_status(httpd_req_t *req, const char *status, const char
     return httpd_resp_send(req, body, body ? HTTPD_RESP_USE_STRLEN : 0);
 }
 
+// Tracks when the previous /frame response finished so we can log the
+// idle gap until the next request enters. Large idle = Scrypted/network
+// upstream is the bottleneck; small idle = we're saturating the link.
+static int64_t s_last_post_us;
+
 static esp_err_t frame_post_handler(httpd_req_t *req)
 {
     // Content-Type must be image/jpeg.
@@ -417,16 +422,28 @@ static esp_err_t frame_post_handler(httpd_req_t *req)
     // draw_bitmap-returns and the response-send adds up.
     t_post = esp_timer_get_time();
 
+    // Idle gap = time from the PREVIOUS /frame response finishing to
+    // THIS request landing on the handler. Large gap = upstream
+    // (Scrypted / ffmpeg / TCP slow-start on a fresh socket) was idle;
+    // we're not the bottleneck. Skipped on the very first frame.
+    int64_t idle_us = s_last_post_us ? (t_entry - s_last_post_us) : 0;
+    s_last_post_us = t_post;
+
     // Timing log every 10 frames so the user can see where each /frame's
-    // wall-clock budget is going. Sub-breakdown of the previously-fat
-    // "recv" bucket: lock acquire + first-byte (TCP setup / TTFB) +
-    // body (actual data wire-time). Post-paint bookkeeping is the
-    // bookkeeping after draw_bitmap returns (state counters + unlock).
+    // wall-clock budget is going. Buckets:
+    //   idle  : time since the previous response finished (upstream gap)
+    //   lock  : mutex acquire
+    //   ttfb  : lock-acquired -> first body byte (TCP setup)
+    //   body  : remaining body bytes (wire time)
+    //   dec   : hardware JPEG decode
+    //   paint : esp_lcd_panel_draw_bitmap → DSI fast-path
+    //   post  : state counters + unlock
     if (fr % 10 == 0) {
         ESP_LOGI(TAG,
-            "frame %llu: lock=%lldus ttfb=%lldus body=%lldus "
+            "frame %llu: idle=%lldus lock=%lldus ttfb=%lldus body=%lldus "
             "dec=%lldus paint=%lldus post=%lldus total=%lldms (jpeg=%uKB)",
             (unsigned long long)fr,
+            (long long)idle_us,
             (long long)(t_lock       - t_entry),
             (long long)(t_first_byte - t_lock),
             (long long)(t_recv       - t_first_byte),
diff --git a/scrypted/scrypted-viewport.ts b/scrypted/scrypted-viewport.ts
index fb2c4b8..a782745 100644
--- a/scrypted/scrypted-viewport.ts
+++ b/scrypted/scrypted-viewport.ts
@@ -713,14 +713,26 @@ class ScryptedViewportProvider extends ScryptedDeviceBase
         }
     }
 
+    // Scrypted-side per-fetch timing — mirrors the firmware's per-frame
+    // log. Counter advanced in the stdout demux loop; logged once every
+    // 10 fetches alongside the wall-clock duration of the fetch itself.
+    private fetchCount = new Map<string, number>();
+
     private async pushStreamFrame(v: Viewport, jpeg: Buffer, abort: AbortController) {
         if (abort.signal.aborted) return;
+        const t0 = Date.now();
         const res = await fetch(`http://${v.host}/frame`, {
             method: "POST",
             headers: { "Content-Type": "image/jpeg" },
             body: jpeg,
             signal: abort.signal,
         });
+        const wallMs = Date.now() - t0;
+        const n = (this.fetchCount.get(v.nativeId!) || 0) + 1;
+        this.fetchCount.set(v.nativeId!, n);
+        if (n % 10 === 0) {
+            this.console.log(`fetch "${v.name}" #${n}: ${wallMs}ms wall (jpeg=${(jpeg.length / 1024).toFixed(0)}KB)`);
+        }
         if (res.status === 409) {
             this.console.log(`"${v.name}" returned 409 — device went to sleep, stopping stream`);
             this.stopStream(v.name, /*sendSleep=*/ false);