From 72092625e073699e30260d61047c113025229864 Mon Sep 17 00:00:00 2001 From: Grace Kind Date: Sun, 2 Aug 2026 23:46:13 -0500 Subject: [PATCH] Tweak slot monitor logic --- package.json | 2 +- src/js/components/plugin-slot.js | 39 +++- src/js/plugins/pluginSlotDispatcher.js | 39 ++-- src/js/utils.js | 55 ++++++ .../unit/specs/components/plugin-slot.test.js | 153 ++++++++++++++- .../plugins/pluginSlotDispatcher.test.js | 19 +- tests/unit/specs/utils.test.js | 176 ++++++++++++++++++ 7 files changed, 443 insertions(+), 40 deletions(-) diff --git a/package.json b/package.json index 7c406e58..10311c1c 100644 --- a/package.json +++ b/package.json @@ -1,6 +1,6 @@ { "name": "impro", - "version": "0.18.145", + "version": "0.18.146", "type": "module", "scripts": { "start": "rm -rf \"${BUILD_DIR:-build}\" && NODE_ENV=development eleventy --serve", diff --git a/src/js/components/plugin-slot.js b/src/js/components/plugin-slot.js index abfa45c4..479e4cdc 100644 --- a/src/js/components/plugin-slot.js +++ b/src/js/components/plugin-slot.js @@ -1,13 +1,47 @@ import { Component } from "/js/components/component.js"; import { effect } from "/js/signals.js"; -import { isPromise } from "/js/utils.js"; +import { isDev, isPromise, throttleByKey, WindowedCounter } from "/js/utils.js"; const CONTEXT_PREFIX = "context-"; +const REPEAT_WINDOW_MS = 5000; +const REPEAT_REQUEST_LIMIT = 5; function kebabToCamel(name) { return name.replace(/-([a-z])/g, (_, char) => char.toUpperCase()); } +// Dedupe warnings within the window +const warnRepeatRequests = throttleByKey( + (slotKey, message) => console.warn(message), + { delay: REPEAT_WINDOW_MS }, +); + +// Warns on repeat slot requests - this can happen due to +// context churn on the host side or a refreshSlot loop +// on the plugin side +class RepeatRequestMonitor { + constructor() { + this._counter = new WindowedCounter({ + windowMs: REPEAT_WINDOW_MS, + limit: REPEAT_REQUEST_LIMIT, + }); + } + + record(pluginId, slotName, contextKey) { + const exceeded = this._counter.record(pluginId, contextKey); + if (!exceeded) return; + const seconds = REPEAT_WINDOW_MS / 1000; + warnRepeatRequests( + JSON.stringify([pluginId, slotName]), + `[plugins] "${pluginId}" slot "${slotName}" was re-requested ${exceeded.total} times in ${seconds}s by a single mounted slot, across ${exceeded.distinct} contexts (latest: ${contextKey}). Look for a refreshSlot loop, or a context attribute that changes on every render.`, + ); + } + + clear() { + this._counter.clear(); + } +} + class PluginSlot extends Component { connectedCallback() { if (!this.initialized) { @@ -18,6 +52,7 @@ class PluginSlot extends Component { // pluginId -> { root, element, version, contextKey } this._pluginRenderState = new Map(); this._currentRequest = null; + this._repeatMonitor = isDev() ? new RepeatRequestMonitor() : null; } this._subscribe(); } @@ -38,6 +73,7 @@ class PluginSlot extends Component { this._disposeEffect = null; this._currentRequest = null; this._pluginRenderState.clear(); + this._repeatMonitor?.clear(); } static get observedAttributes() { @@ -107,6 +143,7 @@ class PluginSlot extends Component { ); return { registration, version, contextKey, node: null }; }; + this._repeatMonitor?.record(registration.pluginId, slotName, contextKey); let content = null; try { content = registration.request(context); diff --git a/src/js/plugins/pluginSlotDispatcher.js b/src/js/plugins/pluginSlotDispatcher.js index 5d8482d4..376343b8 100644 --- a/src/js/plugins/pluginSlotDispatcher.js +++ b/src/js/plugins/pluginSlotDispatcher.js @@ -5,6 +5,7 @@ import { BoundedMap, isDev, SimpleUUID, + WindowedCounter, } from "/js/utils.js"; // Rendered content cached per cacheKey-declaring registration @@ -164,44 +165,26 @@ function invocationAdvice(cacheKey) { } const INVOCATION_WINDOW_MS = 5000; -const REPEAT_CONTEXT_LIMIT = 5; const TOTAL_INVOCATION_LIMIT = 100; // Warns when a slot handler runs too often in a given window export class SlotInvocationMonitor { constructor() { - this.buckets = new Map(); + this._counter = new WindowedCounter({ + windowMs: INVOCATION_WINDOW_MS, + limit: TOTAL_INVOCATION_LIMIT, + }); } record(registration, name, context) { const id = createSlotId(registration.pluginId, name); - const now = Date.now(); - let bucket = this.buckets.get(id); - if (!bucket || now - bucket.startedAt > INVOCATION_WINDOW_MS) { - bucket = { startedAt: now, total: 0, contexts: new Map(), warned: false }; - this.buckets.set(id, bucket); - } - bucket.total += 1; - const contextKey = serializeFields(context); - const repeats = (bucket.contexts.get(contextKey) ?? 0) + 1; - bucket.contexts.set(contextKey, repeats); - if (bucket.warned) return; + const exceeded = this._counter.record(id, serializeFields(context)); + if (!exceeded) return; const seconds = INVOCATION_WINDOW_MS / 1000; - const prefix = `[plugins] "${registration.pluginId}" slot "${name}" ran`; - if (repeats >= REPEAT_CONTEXT_LIMIT) { - bucket.warned = true; - console.warn( - `${prefix} ${repeats} times for the same context in ${seconds}s: ${contextKey}. Look for a refreshSlot loop, or a context attribute that changes on every render.`, - ); - return; - } - if (bucket.total >= TOTAL_INVOCATION_LIMIT) { - bucket.warned = true; - const advice = invocationAdvice(registration.cacheKey); - console.warn( - `${prefix} ${bucket.total} times in ${seconds}s across ${bucket.contexts.size} contexts. ${advice}`, - ); - } + const advice = invocationAdvice(registration.cacheKey); + console.warn( + `[plugins] "${registration.pluginId}" slot "${name}" ran ${exceeded.total} times in ${seconds}s across ${exceeded.distinct} contexts. ${advice}`, + ); } } diff --git a/src/js/utils.js b/src/js/utils.js index 11bd5f09..540ed8cc 100644 --- a/src/js/utils.js +++ b/src/js/utils.js @@ -286,6 +286,24 @@ export function throttle(fn, delay = 250) { }; } +// Throttle calls that share a key (by default, the first arg) +export function throttleByKey( + fn, + { delay = 250, getKey = (first) => first } = {}, +) { + const lastCalls = new Map(); + return (...args) => { + const key = getKey(...args); + const now = Date.now(); + const lastCall = lastCalls.get(key); + if (lastCall !== undefined && now - lastCall < delay) { + return; + } + lastCalls.set(key, now); + fn(...args); + }; +} + export class BoundedMap extends Map { constructor(maxSize, { onEvict = noop, policy = "fifo" } = {}) { super(); @@ -385,6 +403,43 @@ export class AsyncValueCache { } } +// Counts events inside a tumbling window. `record` returns null until a +// key reaches `limit` within one window, then returns that window's +// `{ total, distinct }`. A tag can optionally be passed per-event; +// `distinct` counts the number of distinct tags seen per-key. +export class WindowedCounter { + constructor({ windowMs, limit }) { + this._windowMs = windowMs; + this._limit = limit; + // key -> { startedAt, total, tags, reported } + this._buckets = new Map(); + } + + record(key, tag = null) { + const now = Date.now(); + let bucket = this._buckets.get(key); + if (!bucket || now - bucket.startedAt > this._windowMs) { + bucket = { startedAt: now, total: 0, tags: null, reported: false }; + this._buckets.set(key, bucket); + } + if (bucket.reported) return null; + bucket.total += 1; + if (tag !== null) { + if (!bucket.tags) bucket.tags = new Set(); + bucket.tags.add(tag); + } + if (bucket.total < this._limit) return null; + bucket.reported = true; + const distinct = bucket.tags ? bucket.tags.size : null; + bucket.tags = null; + return { total: bucket.total, distinct }; + } + + clear() { + this._buckets.clear(); + } +} + // Turns a batch function into a single-item function - // calls made in the same microtask are collected and run together, // then results are resolved / rejected individually diff --git a/tests/unit/specs/components/plugin-slot.test.js b/tests/unit/specs/components/plugin-slot.test.js index 600280ea..251dedcc 100644 --- a/tests/unit/specs/components/plugin-slot.test.js +++ b/tests/unit/specs/components/plugin-slot.test.js @@ -1,4 +1,4 @@ -import { describe, it, beforeEach } from "node:test"; +import { describe, it, beforeEach, afterEach } from "node:test"; import assert from "node:assert/strict"; import { SignalMap } from "/js/signals.js"; import { makeTestPluginService } from "../../testHelpers.js"; @@ -660,4 +660,155 @@ describe("plugin-slot", () => { assert.deepEqual(slot.children[0].textContent, "A"); }); }); + + describe("PluginSlot - repeat request monitor", () => { + const warnings = []; + let now = 1_000_000; + const originalWarn = console.warn; + const originalNow = Date.now; + + beforeEach(() => { + warnings.length = 0; + // The one-warning-per-slot-per-window gate is module-level, so each + // test has to start well past the previous test's window + now += 1_000_000; + console.warn = (...args) => warnings.push(args.join(" ")); + Date.now = () => now; + }); + + afterEach(() => { + console.warn = originalWarn; + Date.now = originalNow; + }); + + function makeVersionedService() { + const registrations = [ + { + pluginId: "alpha", + version: 0, + invoke: async () => ({ tag: "div", text: "A" }), + }, + ]; + const pluginService = makePluginService({ + registrations: { "author-badges": registrations }, + }); + return { pluginService, registrations }; + } + + it("warns once when one mounted slot re-requests past the limit", async () => { + const { pluginService, registrations } = makeVersionedService(); + const slot = makeSlot({ + pluginService, + name: "author-badges", + context: { did: "did:plc:one" }, + }); + document.body.appendChild(slot); + await flushMicrotasks(); + + for (let i = 0; i < 6; i++) { + registrations[0].version += 1; + pluginService.setSlotRegistrations("author-badges", registrations); + await flushMicrotasks(); + } + assert.deepEqual(warnings.length, 1); + assert(warnings[0].includes("re-requested 5 times in 5s")); + assert(warnings[0].includes("across 1 contexts")); + assert(warnings[0].includes("refreshSlot loop")); + }); + + it("reports the distinct contexts when a context attribute churns", async () => { + const { pluginService } = makeVersionedService(); + const slot = makeSlot({ + pluginService, + name: "author-badges", + context: { did: "did:plc:0" }, + }); + document.body.appendChild(slot); + await flushMicrotasks(); + + for (let i = 1; i < 6; i++) { + slot.setAttribute("context-did", `did:plc:${i}`); + await flushMicrotasks(); + } + assert.deepEqual(warnings.length, 1); + assert(warnings[0].includes("across 5 contexts")); + }); + + // The case the dispatcher-level check got wrong: a page rendering the same + // slot many times for one author is not a loop. + it("stays quiet when many mounted slots share one context", async () => { + const { pluginService } = makeVersionedService(); + for (let i = 0; i < 10; i++) { + document.body.appendChild( + makeSlot({ + pluginService, + name: "author-badges", + context: { did: "did:plc:one" }, + }), + ); + } + await flushMicrotasks(); + assert.deepEqual(warnings, []); + }); + + // One loop trips every mounted slot at once, so the warning is shared + it("warns once when the whole page's slots re-request past the limit", async () => { + const { pluginService, registrations } = makeVersionedService(); + for (let i = 0; i < 10; i++) { + document.body.appendChild( + makeSlot({ + pluginService, + name: "author-badges", + context: { did: `did:plc:${i}` }, + }), + ); + } + await flushMicrotasks(); + + for (let i = 0; i < 6; i++) { + registrations[0].version += 1; + pluginService.setSlotRegistrations("author-badges", registrations); + await flushMicrotasks(); + } + assert.deepEqual(warnings.length, 1); + }); + + it("warns again for a loop that outlives the window", async () => { + const { pluginService, registrations } = makeVersionedService(); + const slot = makeSlot({ + pluginService, + name: "author-badges", + context: { did: "did:plc:one" }, + }); + document.body.appendChild(slot); + await flushMicrotasks(); + + for (let i = 0; i < 12; i++) { + now += 1000; + registrations[0].version += 1; + pluginService.setSlotRegistrations("author-badges", registrations); + await flushMicrotasks(); + } + assert.deepEqual(warnings.length, 2); + }); + + it("stays quiet for repeats spread across separate windows", async () => { + const { pluginService, registrations } = makeVersionedService(); + const slot = makeSlot({ + pluginService, + name: "author-badges", + context: { did: "did:plc:one" }, + }); + document.body.appendChild(slot); + await flushMicrotasks(); + + for (let i = 0; i < 10; i++) { + now += 5001; + registrations[0].version += 1; + pluginService.setSlotRegistrations("author-badges", registrations); + await flushMicrotasks(); + } + assert.deepEqual(warnings, []); + }); + }); }); diff --git a/tests/unit/specs/plugins/pluginSlotDispatcher.test.js b/tests/unit/specs/plugins/pluginSlotDispatcher.test.js index 321eabb6..21dae029 100644 --- a/tests/unit/specs/plugins/pluginSlotDispatcher.test.js +++ b/tests/unit/specs/plugins/pluginSlotDispatcher.test.js @@ -584,20 +584,20 @@ describe("PluginSlotDispatcher - invocation monitor", () => { Date.now = originalNow; }); - it("warns once when one context is re-invoked five times in the window", async () => { + // A slot can be mounted many times per page with the same context, so + // repeats alone say nothing at this layer - only volume does. + it("stays quiet when one context is re-invoked by many mounted slots", async () => { const { registration } = register(makeDispatcher()); - for (let i = 0; i < 7; i++) { + for (let i = 0; i < 20; i++) { await registration.request({ did: "did:one" }); } - assert.deepEqual(warnings.length, 1); - assert(warnings[0].includes("5 times for the same context")); - assert(warnings[0].includes("refreshSlot loop")); + assert.deepEqual(warnings, []); }); - it("stays quiet for repeats spread across separate windows", async () => { + it("stays quiet for high volume spread across separate windows", async () => { const { registration } = register(makeDispatcher()); - for (let i = 0; i < 10; i++) { - await registration.request({ did: "did:one" }); + for (let i = 0; i < 300; i++) { + await registration.request({ did: `did:${i}` }); now += 5001; } assert.deepEqual(warnings, []); @@ -638,7 +638,8 @@ describe("PluginSlotDispatcher - invocation monitor", () => { it("counts cache hits as no invocation at all", async () => { const { registration } = register(makeDispatcher(), { cacheKey: ["did"] }); - for (let i = 0; i < 20; i++) { + // Past the volume limit, so a cache hit counted as an invocation would warn + for (let i = 0; i < 150; i++) { const request = registration.request({ uri: `at://${i}`, did: "did:one", diff --git a/tests/unit/specs/utils.test.js b/tests/unit/specs/utils.test.js index fd9b507a..ef94c500 100644 --- a/tests/unit/specs/utils.test.js +++ b/tests/unit/specs/utils.test.js @@ -31,6 +31,8 @@ import { BoundedMap, AsyncValueCache, isPromise, + throttleByKey, + WindowedCounter, } from "/js/utils.js"; import { installFakeIndexedDB } from "../testHelpers.js"; @@ -1679,3 +1681,177 @@ describe("AsyncValueCache", () => { assert.deepEqual(cache.peek("a").value, "A"); }); }); + +describe("throttleByKey", () => { + let now = 1_000_000; + const originalNow = Date.now; + + beforeEach(() => { + now = 1_000_000; + Date.now = () => now; + }); + + afterEach(() => { + Date.now = originalNow; + }); + + function makeThrottled(options = {}) { + const calls = []; + const throttled = throttleByKey((...args) => calls.push(args), { + delay: 250, + ...options, + }); + return { calls, throttled }; + } + + it("calls through on the leading edge and swallows the rest", () => { + const { calls, throttled } = makeThrottled(); + throttled("a"); + throttled("a"); + now += 249; + throttled("a"); + assert.deepEqual(calls, [["a"]]); + }); + + it("keys on the first argument by default, ignoring the rest", () => { + const { calls, throttled } = makeThrottled(); + throttled("a", 1); + throttled("a", 2); + assert.deepEqual(calls, [["a", 1]]); + }); + + it("gives each key its own window", () => { + const { calls, throttled } = makeThrottled(); + throttled("a"); + throttled("b"); + throttled("a"); + assert.deepEqual(calls, [["a"], ["b"]]); + }); + + it("passes the key through to the wrapped function", () => { + const { calls, throttled } = makeThrottled(); + throttled("a", "extra"); + assert.deepEqual(calls, [["a", "extra"]]); + }); + + it("calls through again once the delay has passed", () => { + const { calls, throttled } = makeThrottled(); + throttled("a"); + now += 250; + throttled("a"); + assert.deepEqual(calls, [["a"], ["a"]]); + }); + + it("throttles on a getKey built from several arguments", () => { + const { calls, throttled } = makeThrottled({ + getKey: (name, index) => `${name}${index}`, + }); + throttled("a", 1); + throttled("a", 2); + throttled("a", 1); + assert.deepEqual(calls, [ + ["a", 1], + ["a", 2], + ]); + }); +}); + +describe("WindowedCounter", () => { + let now = 1_000_000; + const originalNow = Date.now; + + beforeEach(() => { + now = 1_000_000; + Date.now = () => now; + }); + + afterEach(() => { + Date.now = originalNow; + }); + + function makeCounter({ limit = 3, windowMs = 5000 } = {}) { + return new WindowedCounter({ windowMs, limit }); + } + + it("returns null until a key reaches the limit", () => { + const counter = makeCounter(); + assert.deepEqual(counter.record("a", "x"), null); + assert.deepEqual(counter.record("a", "x"), null); + const exceeded = counter.record("a", "x"); + assert.deepEqual(exceeded.total, 3); + }); + + it("counts the distinct tags seen in the window", () => { + const counter = makeCounter(); + counter.record("a", "x"); + counter.record("a", "y"); + const exceeded = counter.record("a", "y"); + assert.deepEqual(exceeded.distinct, 2); + }); + + it("reports a null distinct count when no tags are given", () => { + const counter = makeCounter(); + counter.record("a"); + counter.record("a"); + assert.deepEqual(counter.record("a"), { total: 3, distinct: null }); + }); + + it("counts only the tags it was given when some events are untagged", () => { + const counter = makeCounter(); + counter.record("a"); + counter.record("a", "x"); + assert.deepEqual(counter.record("a"), { total: 3, distinct: 1 }); + }); + + it("reports only once per window", () => { + const counter = makeCounter(); + const results = Array.from({ length: 10 }, () => counter.record("a", "x")); + assert.deepEqual(results.filter(Boolean).length, 1); + }); + + it("stops counting once a window has reported", () => { + const counter = makeCounter(); + counter.record("a", "x"); + counter.record("a", "x"); + const exceeded = counter.record("a", "x"); + assert.deepEqual(exceeded, { total: 3, distinct: 1 }); + for (let i = 0; i < 20; i++) counter.record("a", `tag-${i}`); + // The next window starts from scratch rather than inheriting those events + now += 5001; + counter.record("a", "x"); + counter.record("a", "x"); + assert.deepEqual(counter.record("a", "y"), { total: 3, distinct: 2 }); + }); + + it("reports again after the window rolls over", () => { + const counter = makeCounter(); + for (let i = 0; i < 3; i++) counter.record("a", "x"); + now += 5001; + assert.deepEqual(counter.record("a", "x"), null); + counter.record("a", "x"); + assert.deepEqual(counter.record("a", "x").total, 3); + }); + + it("stays under the limit when events straddle windows", () => { + const counter = makeCounter(); + for (let i = 0; i < 10; i++) { + assert.deepEqual(counter.record("a", "x"), null); + now += 5001; + } + }); + + it("counts each key separately", () => { + const counter = makeCounter(); + for (let i = 0; i < 5; i++) { + assert.deepEqual(counter.record(`key-${i}`, "x"), null); + } + }); + + it("forgets everything on clear", () => { + const counter = makeCounter(); + counter.record("a", "x"); + counter.record("a", "x"); + counter.clear(); + assert.deepEqual(counter.record("a", "x"), null); + }); +}); -- 2.51.2