diff options
| author | Luke Hoersten <[email protected]> | 2026-06-20 11:54:14 -0500 |
|---|---|---|
| committer | Luke Hoersten <[email protected]> | 2026-06-20 11:54:14 -0500 |
| commit | 28f39bf5102ef398b6e91fdf61e7583c99d7252c (patch) | |
| tree | 140c2dc96ee37d507afcaa0a0b18338f6ec60ced | |
| parent | 16f4c5be220756808747bfb47739733d3f107634 (diff) | |
scrypted: kill listener leak across script reloads + one-line sent-vs-painted log
#1 — Camera listener leak
Same Scripts-sandbox lifecycle gap that bit us with setInterval (fixed
in 521de7e): cam.listen() returns an EventListenerRegister with a
removeListener() method. The listener is held on the camera plugin's
side, not the script's, so when the old Provider instance gets GC'd
on script reload its registrations stay live with a dead callback.
Field symptom: after re-pasting the script N times, every camera
event arrives N times in handleCameraEvent. Today the streamStarting
guard catches sequential dupes, but two callbacks firing on the same
event within the JS microtask window both check streamStarting
BEFORE either has added their nativeId, both proceed, two
pushSnapshots launch in parallel. They race for the firmware
decoder lock — one paints, one gets 503 — and the user perceives
sharp-fighting-with-itself as "snapshot quality is bad again."
Fix: same globalThis trick as the setInterval. Push a remover
closure onto G.__viewportListenerCleaners every time attachListener
fires; at start() of the new Provider instance, drain the array
calling each remover before creating fresh listeners. Idempotent
across reloads.
#2 — Unified sent-vs-painted log
The user asked: "do we have an understanding in the logging/
instrumentation what the FPS of the stream output is from scrypted
out is vs the actual rendered FPS once the stream is loaded?"
Both numbers existed but in separate log lines (skipLogger every 10s
+ fwPoller every 5s, interleaved in the console). Folded the /state
poll into the 10s skipLogger so there's ONE line per window with
sent fps + painted fps side-by-side plus the gap explicitly labeled:
stream "kitchen": sent=24.2fps painted=22.8fps (fw-skipped=1.4fps,
drops=0) 4.58MB/s sent / 4.29MB/s painted |
socket.write p50=0ms p95=1ms max=5ms backpressured=true |
recv=27776/37237/44470us dec=5788/5991/6626us
paint=30/36/46us idle=164/588/11383us | g2g=142ms
fw-skipped = (sent − painted), how many frames per second the
firmware's FIONREAD skip dropped to keep the panel on the freshest
frame. The g2g value is now meaningful per-frame thanks to the
firmware-side live-update we landed last commit.
Drops the separate fwPoller; one comprehensive log per 10s window.
| -rw-r--r-- | scrypted/scrypted-viewport.ts | 131 |
1 files changed, 75 insertions, 56 deletions
diff --git a/scrypted/scrypted-viewport.ts b/scrypted/scrypted-viewport.ts index 56b7186..7156fba 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 = "568de10"; +const SCRIPT_VERSION = "pending"; // // Architecture // ------------ @@ -366,6 +366,18 @@ class ScryptedViewportProvider extends ScryptedDeviceBase if (G.__viewportRegisterInterval) { try { clearInterval(G.__viewportRegisterInterval); } catch {} } + // Tear down any camera event listeners left over from a + // previous script load (same Scripts-sandbox lifecycle gap as + // the setInterval handle). Without this every re-paste stacks + // an extra callback on the camera, producing duplicate stream + // starts + concurrent snapshot transforms that race for the + // firmware decoder lock and visibly degrade quality. + if (Array.isArray(G.__viewportListenerCleaners)) { + for (const remove of G.__viewportListenerCleaners) { + try { remove(); } catch {} + } + } + G.__viewportListenerCleaners = []; G.__viewportRegisterInterval = setInterval(() => { for (const v of this.viewports.values()) { this.registerViewport(v).catch(() => {}); @@ -539,6 +551,16 @@ class ScryptedViewportProvider extends ScryptedDeviceBase this.handleCameraEvent(v, details, data); }); this.listeners.set(v.nativeId!, reg); + // Track on globalThis so script reload can remove this + // listener from the camera plugin. Without that, every + // re-paste leaves a dead callback subscribed to the camera + // and every motion/doorbell event triggers handleCameraEvent + // N times for N stacked reloads — observable as duplicate + // "stream start" log lines + two simultaneous pushSnapshots + // racing for the firmware decoder lock. + const G = globalThis as any; + if (!G.__viewportListenerCleaners) G.__viewportListenerCleaners = []; + G.__viewportListenerCleaners.push(() => { try { reg.removeListener(); } catch {} }); this.console.log(`viewport "${tag}": subscribed to "${cam.name}"`); } @@ -953,70 +975,67 @@ class ScryptedViewportProvider extends ScryptedDeviceBase try { currentProc?.kill("SIGTERM"); } catch {} }); - // Periodic stream-health log. Emits delivered fps + sustained - // MB/s + socket.write p50/p95/max + drop count + backpressure - // flag every 10s. drops here count frames the demux loop - // threw away because the socket wasn't connected yet (initial - // race at stream start) — once the socket is up we keep - // writing past kernel backpressure and let the firmware's - // FIONREAD skip drop the stale frames before decode. - const skipLogger = setInterval(() => { + // Unified stream-health log every 10s: Scrypted-side sent fps + // + firmware-side painted fps side-by-side, so the user can + // see at a glance "we sent N, the panel showed M." The gap + // (sent - painted) is what the firmware's FIONREAD skip + // dropped to keep the panel showing the freshest frame. + // Includes firmware-side per-stage timings (recv/dec/paint/ + // idle min/avg/max) + glass-to-glass age of the most recent + // painted frame. /state poll is folded in so there's one log + // line per window instead of two interleaved timelines. + const streamLogger = setInterval(async () => { const now = Date.now(); const window = (now - lastLogUs) / 1000; - if (window > 0 && (sentFrames > 0 || droppedFrames > 0)) { - const sentRate = sentFrames / window; - const dropRate = droppedFrames / window; - const mbPerSec = (bytesSent / window) / (1024 * 1024); - const sortedW = writeLatencies.slice().sort((a, b) => a - b); - const p50 = sortedW.length ? sortedW[Math.floor(sortedW.length * 0.5)] : 0; - const p95 = sortedW.length ? sortedW[Math.floor(sortedW.length * 0.95)] : 0; - const max = sortedW.length ? sortedW[sortedW.length - 1] : 0; - this.console.log( - `stream "${v.name}": ${sentRate.toFixed(1)} fps, ${mbPerSec.toFixed(2)} MB/s ` + - `over ${window.toFixed(1)}s ` + - `(drops=${droppedFrames}=${dropRate.toFixed(1)} fps) ` + - `socket.write p50=${p50}ms p95=${p95}ms max=${max}ms ` + - `backpressured=${socketBackpressured}`); - droppedFrames = 0; - sentFrames = 0; - bytesSent = 0; - writeLatencies.length = 0; - lastLogUs = now; - } - }, 10_000); - abort.signal.addEventListener("abort", () => clearInterval(skipLogger)); - - // Periodic /state poll to surface firmware-side window stats + - // computed glass-to-glass. Runs every 5s while the stream is - // active. g2g = (nowUsLow - last_paint_event_us_low) with - // 32-bit wrap; clamped to a 30s sanity ceiling because event - // timestamps from before the stream started are stale and - // would yield gigantic apparent latencies. - const fwPoller = setInterval(async () => { + if (window <= 0 || (sentFrames === 0 && droppedFrames === 0)) return; + const sentRate = sentFrames / window; + const dropRate = droppedFrames / window; + const mbPerSec = (bytesSent / window) / (1024 * 1024); + const sortedW = writeLatencies.slice().sort((a, b) => a - b); + const p50 = sortedW.length ? sortedW[Math.floor(sortedW.length * 0.5)] : 0; + const p95 = sortedW.length ? sortedW[Math.floor(sortedW.length * 0.95)] : 0; + const max = sortedW.length ? sortedW[sortedW.length - 1] : 0; + + // Best-effort firmware-side snapshot. Timeout < 1s so a + // missed /state never wedges the logger. + let painted = "?", paintedMb = "?", g2g = "?", paintedNum = -1; + let recvStr = "?", decStr = "?", paintStr = "?", idleStr = "?"; try { const st: any = await fetch(`http://${v.host}/state`, { - signal: AbortSignal.timeout(1500), + signal: AbortSignal.timeout(800), }).then(r => r.json()); const fs = st?.stream; - if (!fs || !fs.frames) return; - const fps = fs.window_us > 0 ? (fs.frames / (fs.window_us / 1e6)) : 0; - const mb = fs.window_us > 0 ? ((fs.bytes / (fs.window_us / 1e6)) / (1024 * 1024)) : 0; - let g2gMs = -1; - if (fs.last_paint_event_us_low) { + if (fs?.frames && fs.window_us > 0) { + paintedNum = fs.frames / (fs.window_us / 1e6); + painted = paintedNum.toFixed(1); + paintedMb = ((fs.bytes / (fs.window_us / 1e6)) / (1024 * 1024)).toFixed(2); + recvStr = `${fs.recv_min_us}/${fs.recv_avg_us}/${fs.recv_max_us}`; + decStr = `${fs.dec_min_us}/${fs.dec_avg_us}/${fs.dec_max_us}`; + paintStr = `${fs.paint_min_us}/${fs.paint_avg_us}/${fs.paint_max_us}`; + idleStr = `${fs.idle_min_us}/${fs.idle_avg_us}/${fs.idle_max_us}`; + } + if (fs?.last_paint_event_us_low) { const nowUsLow = (Date.now() * 1000) >>> 0; const diff = (nowUsLow - fs.last_paint_event_us_low) >>> 0; - if (diff < 30_000_000) g2gMs = diff / 1000; + if (diff < 30_000_000) g2g = (diff / 1000).toFixed(0) + "ms"; } - this.console.log( - `firmware "${v.name}": fps=${fps.toFixed(1)} ${mb.toFixed(2)}MB/s | ` + - `recv=${fs.recv_min_us}/${fs.recv_avg_us}/${fs.recv_max_us}us | ` + - `dec=${fs.dec_min_us}/${fs.dec_avg_us}/${fs.dec_max_us}us | ` + - `paint=${fs.paint_min_us}/${fs.paint_avg_us}/${fs.paint_max_us}us | ` + - `idle=${fs.idle_min_us}/${fs.idle_avg_us}/${fs.idle_max_us}us | ` + - `g2g=${g2gMs >= 0 ? g2gMs.toFixed(0) + "ms" : "(no event yet)"}`); - } catch { /* /state timeout is fine, try next tick */ } - }, 5_000); - abort.signal.addEventListener("abort", () => clearInterval(fwPoller)); + } catch { /* keep the local stats; firmware-side just shows ? */ } + + const skipped = paintedNum >= 0 ? Math.max(0, sentRate - paintedNum).toFixed(1) : "?"; + this.console.log( + `stream "${v.name}": sent=${sentRate.toFixed(1)}fps painted=${painted}fps ` + + `(fw-skipped=${skipped}fps, drops=${droppedFrames}) ` + + `${mbPerSec.toFixed(2)}MB/s sent / ${paintedMb}MB/s painted | ` + + `socket.write p50=${p50}ms p95=${p95}ms max=${max}ms backpressured=${socketBackpressured} | ` + + `recv=${recvStr}us dec=${decStr}us paint=${paintStr}us idle=${idleStr}us | g2g=${g2g}`); + + droppedFrames = 0; + sentFrames = 0; + bytesSent = 0; + writeLatencies.length = 0; + lastLogUs = now; + }, 10_000); + abort.signal.addEventListener("abort", () => clearInterval(streamLogger)); const timeoutMs = v.idleTimeoutMs > 0 ? v.idleTimeoutMs : DEFAULT_IDLE_TIMEOUT_MS; const timeout = setTimeout(() => { |
