diff --git a/packages/viewer/src/app.d.ts b/packages/viewer/src/app.d.ts new file mode 100644 index 0000000..bc0833b --- /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 de14f5e..0308f4f 100644 --- a/packages/viewer/src/debug.ts +++ b/packages/viewer/src/debug.ts @@ -1,7 +1,81 @@ +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, 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' + planned: number + reset: 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 1b27e90..6e7a697 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 cb9ec66..9d62648 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 472f7aa..dc53897 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,13 @@ export function create( } }) + // 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 })) diff --git a/packages/viewer/wrangler.jsonc b/packages/viewer/wrangler.jsonc index 7bf6940..6215fbe 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 } + } + } } }