From b74d2be8061029d970388c13717734be00626336 Mon Sep 17 00:00:00 2001 From: James Dabbs Date: Sun, 28 Jun 2026 07:47:26 -0700 Subject: [PATCH 1/2] feat(viewer): instrument SSR with structured Workers Logs telemetry MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Emit one queryable JSON event per SSR phase to Workers Logs, object-logged so each field is an indexable key (joinable to the platform's per-invocation cpuTimeMs/wallTimeMs by requestId): - request: routeId, status, isolate cold flag, cf.verifiedBotCategory - bundle_sync: bundle counts + network fetch ms (a valid I/O-bound timer) - deduce_run: exact spaces/derived counts — the reliable proxy for deduction CPU, since Date.now() is clamped for CPU-bound work on Workers and reads ~0 Prefer Cloudflare's verified bot category over a hand-rolled UA regex, and add an isolate cold-start latch so one-time parse cost can be separated from steady-state request cost. Enable observability (logs + traces) on the graphs env too; it was unset, leaving half the deployment unmonitored. Telemetry only, no behavior change: this instruments the current eager-SSR deduction baseline so we can attribute CPU before the lazy-deduction perf change (perf/viewer-ssr-deduction) lands. --- packages/viewer/src/app.d.ts | 14 +++++ packages/viewer/src/debug.ts | 72 +++++++++++++++++++++++++ packages/viewer/src/gateway.ts | 27 +++++++++- packages/viewer/src/hooks.server.ts | 20 ++++++- packages/viewer/src/stores/deduction.ts | 15 ++++++ packages/viewer/wrangler.jsonc | 16 ++++-- 6 files changed, 159 insertions(+), 5 deletions(-) create mode 100644 packages/viewer/src/app.d.ts diff --git a/packages/viewer/src/app.d.ts b/packages/viewer/src/app.d.ts new file mode 100644 index 00000000..bc0833be --- /dev/null +++ b/packages/viewer/src/app.d.ts @@ -0,0 +1,14 @@ +// See https://svelte.dev/docs/kit/types#app.d.ts +import type { IncomingRequestCfProperties } from '@cloudflare/workers-types' + +declare global { + namespace App { + interface Platform { + // `verifiedBotCategory` (Cloudflare's bot classification, which we read for telemetry) + // isn't yet in the upstream `IncomingRequestCfProperties` type. + cf?: IncomingRequestCfProperties & { verifiedBotCategory?: string } + } + } +} + +export {} diff --git a/packages/viewer/src/debug.ts b/packages/viewer/src/debug.ts index de14f5ec..3d98868a 100644 --- a/packages/viewer/src/debug.ts +++ b/packages/viewer/src/debug.ts @@ -1,7 +1,79 @@ +import { browser, building } from '$app/environment' import createDebug from 'debug' export const debug = createDebug('pi-base:viewer') +// The structured schema we emit to Workers Logs during runtime SSR. Each event +// is one queryable log entry; `requestId` ($metadata.requestId) lets us join +// these back to the platform's own per-invocation telemetry (cpuTimeMs, +// wallTimeMs) so any field below can slice those numbers. +// +// Timing note: on Workers `Date.now()` is clamped and only advances after I/O, +// so wall-clock deltas around *CPU-bound* work read as ~0. We therefore record +// reliable counts (and the platform's cpuTimeMs) rather than home-rolled CPU +// timers; the one `ms` we keep (`bundle_sync`) wraps a real network fetch, where +// the clock does advance. +export type ServerEvent = + | { + // One per SSR Worker invocation (static assets bypass the Worker). Carries + // the SvelteKit route *pattern* — which the platform telemetry can't give + // us — plus the isolate cold flag and Cloudflare's verified bot category. + evt: 'request' + routeId: string | null + method: string + status: number + cold: boolean + botCategory: string | null + } + | { + // One per bundle sync. `changed` is true on a 200 (full parse+transform), + // false on a 304. Counts size the parse/transform work; `ms` is the (valid) + // network fetch duration. + evt: 'bundle_sync' + changed: boolean + spaces: number + properties: number + theorems: number + traits: number + ms: number + } + | { + // One per deduction run. `spaces`/`derived` are exact counts of the work + // actually performed — the reliable proxy for deduction CPU. + evt: 'deduce_run' + spaces: number + derived: number + contradiction: boolean + } + +// Emit one structured Workers Logs event. We log the *object* (not a JSON +// string) so Workers Logs indexes each field as a queryable key, the same way +// the platform's `$workers.*` fields are. No-ops in the browser so we don't spam +// the client console, and while prerendering so logs reflect only real runtime +// invocations — use `debug`/`trace` for client-side tracing. +export function serverLog(event: ServerEvent): void { + if (browser || building) { + return + } + + console.log({ source: 'pi-base:viewer', ...event }) +} + +// Cold-start latch for the current Worker isolate. Module state survives across +// requests in a warm isolate, so the first read returns true (this isolate just +// booted: full JS init + first bundle parse) and every later request reads +// false. Read it from exactly one place per request (hooks.server.ts) so the +// latch flips once; combined with the platform's per-invocation cpuTimeMs this +// separates one-time isolate/parse cost from steady-state request cost. +let warmed = false +export function isolateCold(): boolean { + if (warmed) { + return false + } + warmed = true + return true +} + export type Event = | { event: 'remote_fetch_started'; host: string; branch: string } | { event: 'remote_fetch_complete'; result: unknown } diff --git a/packages/viewer/src/gateway.ts b/packages/viewer/src/gateway.ts index 1b27e903..6e7a697b 100644 --- a/packages/viewer/src/gateway.ts +++ b/packages/viewer/src/gateway.ts @@ -1,7 +1,7 @@ import * as pb from '@pi-base/core' import { Id, type Property, type Space, type Trait } from './models' -import { trace } from './debug' +import { serverLog, trace } from './debug' export type Sync = ( host: string, @@ -24,12 +24,28 @@ export function sync( ): Sync { return async (host: string, branch: string, etag?: string) => { trace({ event: 'remote_fetch_started', host, branch }) + // `ms` wraps the network fetch — real I/O, so the Workers clock advances and + // this is a trustworthy duration (unlike CPU-bound timings). Faithful to + // current behaviour: there is no isolate bundle cache, so every SSR request + // re-fetches and (on a 200) re-parses/transforms the whole bundle. + const startedAt = Date.now() const result = bundle ? { bundle, etag: 'etag' } : await pb.bundle.fetch({ host, branch, etag, fetch }) + const ms = Date.now() - startedAt if (result) { trace({ event: 'remote_fetch_complete', result }) + const { spaces, properties, theorems, traits } = result.bundle + serverLog({ + evt: 'bundle_sync', + changed: true, + spaces: spaces.size, + properties: properties.size, + theorems: theorems.size, + traits: traits.size, + ms, + }) return { spaces: transform(space, result.bundle.spaces), properties: transform(property, result.bundle.properties), @@ -40,6 +56,15 @@ export function sync( } } else if (etag) { trace({ event: 'bundle_unchanged', etag }) + serverLog({ + evt: 'bundle_sync', + changed: false, + spaces: 0, + properties: 0, + theorems: 0, + traits: 0, + ms, + }) } } } diff --git a/packages/viewer/src/hooks.server.ts b/packages/viewer/src/hooks.server.ts index cb9ec669..9d626486 100644 --- a/packages/viewer/src/hooks.server.ts +++ b/packages/viewer/src/hooks.server.ts @@ -1,12 +1,30 @@ import type { Handle } from '@sveltejs/kit' +import { isolateCold, serverLog } from '@/debug' + // See https://kit.svelte.dev/docs/hooks#server-hooks export const handle: Handle = async ({ event, resolve }) => { - return resolve(event, { + const response = await resolve(event, { // We use the `etag` header from S3 to determine whether the bundle has // changed (and deduction needs to be re-run), so we need to preserve it. filterSerializedResponseHeaders(name, _value) { return name === 'etag' }, }) + + // Only SSR/endpoint requests reach this hook — static assets are served by the + // Workers assets layer without invoking the Worker. Logging the route pattern, + // isolate cold flag, and Cloudflare's verified bot category here lets us slice + // the platform's per-invocation cpuTimeMs/wallTimeMs (joined by requestId) by + // page, by cold vs warm isolate, and by human vs crawler. + serverLog({ + evt: 'request', + routeId: event.route.id, + method: event.request.method, + status: response.status, + cold: isolateCold(), + botCategory: event.platform?.cf?.verifiedBotCategory ?? null, + }) + + return response } diff --git a/packages/viewer/src/stores/deduction.ts b/packages/viewer/src/stores/deduction.ts index 472f7aaf..d5601e98 100644 --- a/packages/viewer/src/stores/deduction.ts +++ b/packages/viewer/src/stores/deduction.ts @@ -17,6 +17,7 @@ import type { Trait, Traits, } from '@/models' +import { serverLog } from '@/debug' import { eachTick, read, subscribeUntil } from '@/util' export type State = { @@ -109,6 +110,14 @@ export function create( } }) + // Tally the work actually performed. These exact counts are the reliable + // proxy for deduction CPU on Workers, where wall-clock timers around the + // (CPU-bound) loop are clamped to ~0. Joined to the platform's cpuTimeMs by + // requestId, they show how request cost scales with spaces deduced. + let deduced = 0 + let derived = 0 + let contradiction = false + return eachTick(unchecked, (s: Space, halt: () => void) => { store.update(state => ({ ...state, checking: s.name })) @@ -121,6 +130,7 @@ export function create( if (result.kind === 'contradiction') { store.update(s => ({ ...s, contradiction: result.contradiction })) + contradiction = true halt() return } @@ -137,10 +147,15 @@ export function create( addTraits(newTraits) + deduced += 1 + derived += newTraits.length + store.update(state => ({ ...state, checked: new Set([...state.checked, s.id]), })) + }).then(() => { + serverLog({ evt: 'deduce_run', spaces: deduced, derived, contradiction }) }) } diff --git a/packages/viewer/wrangler.jsonc b/packages/viewer/wrangler.jsonc index 7bf6940b..6215fbed 100644 --- a/packages/viewer/wrangler.jsonc +++ b/packages/viewer/wrangler.jsonc @@ -18,9 +18,10 @@ "directory": ".svelte-kit/cloudflare" }, "env": { + // Persist Workers Logs + traces for both sites (queryable in the dashboard + // and via the observability API). invocation_logs gives per-request + // cpuTimeMs/wallTimeMs; traces give the auto I/O waterfall (bundle fetch). "topology": { - // Persist Workers Logs for the production site (queryable in the - // dashboard and via the observability API). graphs can opt in later. "observability": { "enabled": true, "logs": { @@ -30,6 +31,15 @@ "traces": { "enabled": true, "head_sampling_rate": 1 } } }, - "graphs": {} + "graphs": { + "observability": { + "enabled": true, + "logs": { + "enabled": true, + "invocation_logs": true + }, + "traces": { "enabled": true, "head_sampling_rate": 1 } + } + } } } From 6aa4ce230ae39faf2b5f8436d265cc215b34bd18 Mon Sep 17 00:00:00 2001 From: James Dabbs Date: Sun, 28 Jun 2026 08:28:28 -0700 Subject: [PATCH 2/2] fix(viewer): log deduce_run planned count at run start MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The completion-time count fired after the eager SSR run finished — which on the eager model happens after the response is sent — so the logs were dropped and deduce_run.spaces read 0 in Workers Logs. Log `planned` (unchecked.length) synchronously at run start instead: captured pre-response, it reliably sizes the deduction work each run intends to do, joinable to platform cpuTimeMs. Restores the deduction loop to its original form (only the start-of-run log is added). --- packages/viewer/src/debug.ts | 12 +++++++----- packages/viewer/src/stores/deduction.ts | 19 ++++++------------- 2 files changed, 13 insertions(+), 18 deletions(-) diff --git a/packages/viewer/src/debug.ts b/packages/viewer/src/debug.ts index 3d98868a..0308f4fd 100644 --- a/packages/viewer/src/debug.ts +++ b/packages/viewer/src/debug.ts @@ -38,12 +38,14 @@ export type ServerEvent = ms: number } | { - // One per deduction run. `spaces`/`derived` are exact counts of the work - // actually performed — the reliable proxy for deduction CPU. + // One per deduction run, logged synchronously at run *start*. `planned` is + // the number of spaces the run intends to deduce — the reliable proxy for + // deduction work, since the eager run finishes after the SSR response is + // sent, so a completion-time count is dropped. `reset` marks a full re-run + // (e.g. from a refresh) vs an incremental top-up. evt: 'deduce_run' - spaces: number - derived: number - contradiction: boolean + planned: number + reset: boolean } // Emit one structured Workers Logs event. We log the *object* (not a JSON diff --git a/packages/viewer/src/stores/deduction.ts b/packages/viewer/src/stores/deduction.ts index d5601e98..dc53897b 100644 --- a/packages/viewer/src/stores/deduction.ts +++ b/packages/viewer/src/stores/deduction.ts @@ -110,13 +110,12 @@ export function create( } }) - // Tally the work actually performed. These exact counts are the reliable - // proxy for deduction CPU on Workers, where wall-clock timers around the - // (CPU-bound) loop are clamped to ~0. Joined to the platform's cpuTimeMs by - // requestId, they show how request cost scales with spaces deduced. - let deduced = 0 - let derived = 0 - let contradiction = false + // Log the planned work *synchronously*, before the async loop. On the eager + // SSR model the loop finishes after the response is sent (the page resolves + // as soon as its space is reached), so a completion-time count is dropped; + // `planned` (spaces this run intends to deduce) is captured pre-response and + // reliably sizes the deduction work, joinable to platform cpuTimeMs. + serverLog({ evt: 'deduce_run', planned: unchecked.length, reset }) return eachTick(unchecked, (s: Space, halt: () => void) => { store.update(state => ({ ...state, checking: s.name })) @@ -130,7 +129,6 @@ export function create( if (result.kind === 'contradiction') { store.update(s => ({ ...s, contradiction: result.contradiction })) - contradiction = true halt() return } @@ -147,15 +145,10 @@ export function create( addTraits(newTraits) - deduced += 1 - derived += newTraits.length - store.update(state => ({ ...state, checked: new Set([...state.checked, s.id]), })) - }).then(() => { - serverLog({ evt: 'deduce_run', spaces: deduced, derived, contradiction }) }) }