diff --git a/packages/prepare-flags-definitions/README.md b/packages/prepare-flags-definitions/README.md index e4a6b1cb..88e11e75 100644 --- a/packages/prepare-flags-definitions/README.md +++ b/packages/prepare-flags-definitions/README.md @@ -37,6 +37,20 @@ if (result.created) { At runtime, `@vercel/flags-core` imports this module as a fallback when streaming or polling is unavailable. +## Debugging embedded JSON parsing + +Regenerate the embedded definitions using this version of the package, rebuild your app, and set `VERCEL_FLAGS_DEBUG_EMBEDDED_PARSE=1` in the runtime environment. Updating `@vercel/flags-core` alone does not instrument an existing definitions bundle. + +The first lookup of each distinct embedded datafile logs: + +```text +@vercel/flags-definitions: JSON.parse { durationMs: 0.123, jsonChars: 12345 } +``` + +The example values are illustrative. `durationMs` uses `performance.now()` immediately around `JSON.parse`, excluding module import, authentication lookup, and logging. `jsonChars` is the input string length in UTF-16 code units, not a byte count. No SDK keys or flag contents are logged. + +Parsing remains lazy and memoized: cache hits, missing entries, and additional keys sharing the same datafile do not produce another timing log. Timing and logging are disabled unless the environment variable is exactly `1`. Logging itself can increase overall initialization time, so compare the reported parse duration separately from total init time. + ## Documentation - [Embedded Definitions](https://vercel.com/docs/flags/vercel-flags/sdks/core#embedded-definitions) diff --git a/packages/prepare-flags-definitions/src/index.test.ts b/packages/prepare-flags-definitions/src/index.test.ts index 297d5564..81132488 100644 --- a/packages/prepare-flags-definitions/src/index.test.ts +++ b/packages/prepare-flags-definitions/src/index.test.ts @@ -1,4 +1,5 @@ import { readFile } from 'node:fs/promises'; +import { runInNewContext } from 'node:vm'; import { describe, expect, it, vi } from 'vitest'; import { version as pkgVersion } from '../package.json'; import { @@ -117,6 +118,117 @@ describe('generateDefinitionsModule', () => { }); }); +describe('embedded JSON.parse timing', () => { + const definitions = { flag_a: { value: true } }; + const otherDefinitions = { flag_b: { value: false } }; + + function loadGeneratedModule(debug?: string) { + const source = generateDefinitionsModule( + [ + { key: 'vf_server_test_key', definitions }, + { key: 'prj_test', definitions }, + { key: 'prj_other', definitions: otherDefinitions }, + ], + undefined, + ); + const parse = vi.fn(JSON.parse); + const now = vi + .fn() + .mockReturnValueOnce(10) + .mockReturnValueOnce(10.125) + .mockReturnValueOnce(20) + .mockReturnValueOnce(20.25); + const info = vi.fn(); + // Execute the generated code in isolation, exposing its ESM exports as locals. + const { get } = runInNewContext( + `${source.replace(/^export /gm, '')}\n({ get });`, + { + JSON: { parse }, + performance: { now }, + console: { info }, + process: { env: { VERCEL_FLAGS_DEBUG_EMBEDDED_PARSE: debug } }, + }, + ) as { get(key: string): Record | null }; + return { get, parse, now, info }; + } + + it.each([ + undefined, + '0', + 'true', + ])('does not time or log parsing when the debug setting is %s', (debug) => { + const { get, parse, now, info } = loadGeneratedModule(debug); + expect(parse).not.toHaveBeenCalled(); + expect(get('prj_test')).toEqual(definitions); + expect(parse).toHaveBeenCalledExactlyOnceWith(JSON.stringify(definitions)); + expect(now).not.toHaveBeenCalled(); + expect(info).not.toHaveBeenCalled(); + }); + + it('times only the first parse, including when SDK keys and project IDs share data', () => { + const { get, parse, now, info } = loadGeneratedModule('1'); + expect(parse).not.toHaveBeenCalled(); + expect(now).not.toHaveBeenCalled(); + expect(info).not.toHaveBeenCalled(); + + const first = get('vf_server_test_key'); + expect(first).toEqual(definitions); + expect(get('prj_test')).toBe(first); + expect(get('vf_server_test_key')).toBe(first); + + expect(parse).toHaveBeenCalledExactlyOnceWith(JSON.stringify(definitions)); + expect(now).toHaveBeenCalledTimes(2); + expect(info).toHaveBeenCalledExactlyOnceWith( + '@vercel/flags-definitions: JSON.parse', + { durationMs: 0.125, jsonChars: JSON.stringify(definitions).length }, + ); + expect(now.mock.invocationCallOrder[0]).toBeLessThan( + parse.mock.invocationCallOrder[0]!, + ); + expect(parse.mock.invocationCallOrder[0]).toBeLessThan( + now.mock.invocationCallOrder[1]!, + ); + expect(now.mock.invocationCallOrder[1]).toBeLessThan( + info.mock.invocationCallOrder[0]!, + ); + }); + + it('times each distinct datafile independently', () => { + const { get, parse, now, info } = loadGeneratedModule('1'); + expect(get('prj_test')).toEqual(definitions); + const other = get('prj_other'); + expect(other).toEqual(otherDefinitions); + expect(get('prj_other')).toBe(other); + expect(parse).toHaveBeenCalledTimes(2); + expect(now).toHaveBeenCalledTimes(4); + expect(info).toHaveBeenCalledTimes(2); + expect(info).toHaveBeenLastCalledWith( + '@vercel/flags-definitions: JSON.parse', + { durationMs: 0.25, jsonChars: JSON.stringify(otherDefinitions).length }, + ); + }); + + it('does not parse or log a missing entry', () => { + const { get, parse, now, info } = loadGeneratedModule('1'); + expect(get('missing')).toBeNull(); + expect(parse).not.toHaveBeenCalled(); + expect(now).not.toHaveBeenCalled(); + expect(info).not.toHaveBeenCalled(); + }); + + it('preserves successful parsing and memoization if logging throws', () => { + const { get, parse, info } = loadGeneratedModule('1'); + info.mockImplementation(() => { + throw new Error('Logging unavailable'); + }); + const first = get('prj_test'); + expect(first).toEqual(definitions); + expect(get('prj_test')).toBe(first); + expect(parse).toHaveBeenCalledTimes(1); + expect(info).toHaveBeenCalledTimes(1); + }); +}); + describe('prepareFlagsDefinitions', () => { it('returns { created: false, reason: "no-flags-entries" } when no flags auth is in env', async () => { const result = await prepareFlagsDefinitions({ @@ -148,7 +260,20 @@ describe('prepareFlagsDefinitions', () => { expect(definitionsJs).toMatchInlineSnapshot(` "const memo = (fn) => { let cached; return () => (cached ??= fn()); }; - const _d0 = memo(() => JSON.parse("{\\"flag_a\\":{\\"value\\":true}}")); + function parseDefinitions(json) { + if (typeof process === 'undefined' || process.env.VERCEL_FLAGS_DEBUG_EMBEDDED_PARSE !== '1') return JSON.parse(json); + const start = performance.now(); + const definitions = JSON.parse(json); + const durationMs = performance.now() - start; + try { + console.info('@vercel/flags-definitions: JSON.parse', { durationMs, jsonChars: json.length }); + } catch { + // Diagnostics must not prevent flag evaluation. + } + return definitions; + } + + const _d0 = memo(() => parseDefinitions("{\\"flag_a\\":{\\"value\\":true}}")); const map = { "faab116281fa4201059a73f3ca8b7cad7fce9e1132988008784883fa2c78d64a": _d0, @@ -242,7 +367,20 @@ describe('prepareFlagsDefinitions', () => { expect(definitionsJs).toMatchInlineSnapshot(` "const memo = (fn) => { let cached; return () => (cached ??= fn()); }; - const _d0 = memo(() => JSON.parse("{\\"flag_a\\":{\\"value\\":true}}")); + function parseDefinitions(json) { + if (typeof process === 'undefined' || process.env.VERCEL_FLAGS_DEBUG_EMBEDDED_PARSE !== '1') return JSON.parse(json); + const start = performance.now(); + const definitions = JSON.parse(json); + const durationMs = performance.now() - start; + try { + console.info('@vercel/flags-definitions: JSON.parse', { durationMs, jsonChars: json.length }); + } catch { + // Diagnostics must not prevent flag evaluation. + } + return definitions; + } + + const _d0 = memo(() => parseDefinitions("{\\"flag_a\\":{\\"value\\":true}}")); const map = { "3790790d2dc9b23c4539a9f3c49eb5820e4216daebdd7eeee9136f3ceccc31a3": _d0, @@ -298,7 +436,20 @@ describe('prepareFlagsDefinitions', () => { expect(definitionsJs).toMatchInlineSnapshot(` "const memo = (fn) => { let cached; return () => (cached ??= fn()); }; - const _d0 = memo(() => JSON.parse("{\\"flag_a\\":{\\"value\\":true}}")); + function parseDefinitions(json) { + if (typeof process === 'undefined' || process.env.VERCEL_FLAGS_DEBUG_EMBEDDED_PARSE !== '1') return JSON.parse(json); + const start = performance.now(); + const definitions = JSON.parse(json); + const durationMs = performance.now() - start; + try { + console.info('@vercel/flags-definitions: JSON.parse', { durationMs, jsonChars: json.length }); + } catch { + // Diagnostics must not prevent flag evaluation. + } + return definitions; + } + + const _d0 = memo(() => parseDefinitions("{\\"flag_a\\":{\\"value\\":true}}")); const map = { "prj_oidc_test": _d0, @@ -338,7 +489,20 @@ describe('prepareFlagsDefinitions', () => { expect(definitionsJs).toMatchInlineSnapshot(` "const memo = (fn) => { let cached; return () => (cached ??= fn()); }; - const _d0 = memo(() => JSON.parse("{\\"flag_a\\":{\\"value\\":true}}")); + function parseDefinitions(json) { + if (typeof process === 'undefined' || process.env.VERCEL_FLAGS_DEBUG_EMBEDDED_PARSE !== '1') return JSON.parse(json); + const start = performance.now(); + const definitions = JSON.parse(json); + const durationMs = performance.now() - start; + try { + console.info('@vercel/flags-definitions: JSON.parse', { durationMs, jsonChars: json.length }); + } catch { + // Diagnostics must not prevent flag evaluation. + } + return definitions; + } + + const _d0 = memo(() => parseDefinitions("{\\"flag_a\\":{\\"value\\":true}}")); const map = { "faab116281fa4201059a73f3ca8b7cad7fce9e1132988008784883fa2c78d64a": _d0, @@ -440,8 +604,21 @@ describe('prepareFlagsDefinitions', () => { expect(definitionsJs).toMatchInlineSnapshot(` "const memo = (fn) => { let cached; return () => (cached ??= fn()); }; - const _d0 = memo(() => JSON.parse("{\\"flag_a\\":{\\"value\\":true}}")); - const _d1 = memo(() => JSON.parse("{\\"flag_b\\":{\\"value\\":true}}")); + function parseDefinitions(json) { + if (typeof process === 'undefined' || process.env.VERCEL_FLAGS_DEBUG_EMBEDDED_PARSE !== '1') return JSON.parse(json); + const start = performance.now(); + const definitions = JSON.parse(json); + const durationMs = performance.now() - start; + try { + console.info('@vercel/flags-definitions: JSON.parse', { durationMs, jsonChars: json.length }); + } catch { + // Diagnostics must not prevent flag evaluation. + } + return definitions; + } + + const _d0 = memo(() => parseDefinitions("{\\"flag_a\\":{\\"value\\":true}}")); + const _d1 = memo(() => parseDefinitions("{\\"flag_b\\":{\\"value\\":true}}")); const map = { "faab116281fa4201059a73f3ca8b7cad7fce9e1132988008784883fa2c78d64a": _d0, diff --git a/packages/prepare-flags-definitions/src/index.ts b/packages/prepare-flags-definitions/src/index.ts index 90df2df5..808bd1c6 100644 --- a/packages/prepare-flags-definitions/src/index.ts +++ b/packages/prepare-flags-definitions/src/index.ts @@ -74,9 +74,9 @@ type MapEntry = { * Creates js constants pointing to memoized deduplicated flag definitions. * Output format: * ```js - * const _d0 = memo(() => JSON.parse('...')); - * const _d1 = memo(() => JSON.parse('...')); - * ```` + * const _d0 = memo(() => parseDefinitions('...')); + * const _d1 = memo(() => parseDefinitions('...')); + * ``` */ function generateDefinitionConstants( lines: string[], @@ -92,7 +92,7 @@ function generateDefinitionConstants( definitionConst = `_d${stringToConst.size}`; stringToConst.set(stringified, definitionConst); lines.push( - `const ${definitionConst} = memo(() => JSON.parse(${JSON.stringify(stringified)}));`, + `const ${definitionConst} = memo(() => parseDefinitions(${JSON.stringify(stringified)}));`, ); } @@ -214,11 +214,11 @@ async function fetchDatafile( * The map keys are SHA-256 hashes of the SDK keys so that raw keys * are not embedded in the output. * - * Output format: + * Output format (parseDefinitions wraps JSON.parse with opt-in timing): * ```js * const memo = (fn) => { let cached; return () => (cached ??= fn()); }; - * const _d0 = memo(() => JSON.parse('...')); - * const _d1 = memo(() => JSON.parse('...')); + * const _d0 = memo(() => parseDefinitions('...')); + * const _d1 = memo(() => parseDefinitions('...')); * const map = { "": _d0, "project_id": _d1 }; * export function get(key) { return map[key]?.() ?? null; } * ``` @@ -235,6 +235,19 @@ export function generateDefinitionsModule( const lines: string[] = [ 'const memo = (fn) => { let cached; return () => (cached ??= fn()); };', '', + 'function parseDefinitions(json) {', + " if (typeof process === 'undefined' || process.env.VERCEL_FLAGS_DEBUG_EMBEDDED_PARSE !== '1') return JSON.parse(json);", + ' const start = performance.now();', + ' const definitions = JSON.parse(json);', + ' const durationMs = performance.now() - start;', + ' try {', + " console.info('@vercel/flags-definitions: JSON.parse', { durationMs, jsonChars: json.length });", + ' } catch {', + ' // Diagnostics must not prevent flag evaluation.', + ' }', + ' return definitions;', + '}', + '', ]; // generate js const and capture the const names diff --git a/packages/vercel-flags-core/README.md b/packages/vercel-flags-core/README.md index 55da0bff..03ad15ce 100644 --- a/packages/vercel-flags-core/README.md +++ b/packages/vercel-flags-core/README.md @@ -64,6 +64,36 @@ the environment used for flag evaluation. The header source reads `x-vercel-flags-config-versions` or `flags-config-versions`, with the `x-vercel-` header taking precedence when both are present. +## Initialization performance benchmark + +From this repository, run the network-free scenario matrix: + +```bash +pnpm --filter @vercel/flags-core bench:init +pnpm --filter @vercel/flags-core bench:init --definitions /path/to/datafile.json --samples 20 +``` + +Use `--json` for unrounded phase medians/p95s and path-validation counters. Without a file, the benchmark uses 31 synthetic flags. A supplied file stays local and is not modified; generated copies are removed when the run completes. Project metadata is normalized to synthetic values while preserving the flag and segment payloads. + +Each auth method (SDK key and request-scoped OIDC) is measured with: + +- Embedded definitions only, with stream/polling disabled. +- Embedded definitions and a matching, fresh version header, with streaming enabled to verify that the header bypasses it. +- Embedded definitions and a mocked stream sending a `primed` response. +- No matching embedded entry and a mocked stream sending a full datafile. + +Every cold sample uses a fresh Node process. A second, new client in that process measures warm module, parsed-definition, SDK-key-hash, and OIDC-helper caches. Repeated `initialize()` on the same client is reported separately as `reinit`. There are no timing thresholds: assertions verify paths, authentication, memoization, and stream cancellation rather than machine speed. + +The probes measure `createClient()` separately from `initialize()`, then break initialization into embedded module import, auth/project lookup, SDK-key hashing/cache lookup, embedded `JSON.parse`, header detection, stream initialization, and remaining work. JSON output additionally includes total bundled loading and stream authentication; these are **inclusive** parent/child measurements, not additional time to sum. The main table's phase columns are exclusive, but their separately computed medians need not sum to the median init time. + +The benchmark bundles the current source into a temporary worker and adds probes only to that build. The real controller, embedded loader, OIDC helper, hash implementation, generated definitions, and stream decoder run; only stream transport and credentials are synthetic. Mock response construction, fixture preparation, SDK module loading, validation, and shutdown are outside the measured init interval. Instrumentation has some overhead. No live network latency or Next.js `use cache` wrapper is measured, so these numbers are diagnostic breakdowns rather than deployed latency predictions. + +Run the benchmark's functional tests with: + +```bash +pnpm --filter @vercel/flags-core exec vitest run bench/init.test.ts +``` + ## OpenFeature An OpenFeature-compatible provider is available at `@vercel/flags-core/openfeature`: diff --git a/packages/vercel-flags-core/bench/init-worker.ts b/packages/vercel-flags-core/bench/init-worker.ts new file mode 100644 index 00000000..62d81108 --- /dev/null +++ b/packages/vercel-flags-core/bench/init-worker.ts @@ -0,0 +1,217 @@ +import assert from 'node:assert/strict'; +import { readFileSync } from 'node:fs'; +import { setImmediate } from 'node:timers/promises'; +import { Authentication } from '../src/controller/auth'; +import { BundledSource } from '../src/controller/bundled-source'; +import { HeaderSource } from '../src/controller/header-source'; +import { StreamSource } from '../src/controller/stream-source'; +import { createClient } from '../src/index.default'; +import { setRequestContext } from '../src/test-utils'; +import { begin, finish, measure, measureSync, record } from './profile'; + +const scenario = JSON.parse(process.argv[2]!) as { + name: string; + auth: 'sdk-key' | 'oidc'; + source: 'offline' | 'header' | 'stream'; + embedded: boolean; +}; +const fixture = JSON.parse( + readFileSync(new URL('./manifest.json', import.meta.url), 'utf8'), +) as { + sdkKey: string; + token: string; + projectId: string; + configUpdatedAt: number; + revision: number; + flagCount: number; +}; + +// Never read real credentials or contact a real transport, including OIDC refresh. +process.env.VERCEL_OIDC_TOKEN = fixture.token; +process.env.VERCEL_ENV = 'production'; +process.env.VERCEL_FLAGS_DEBUG_EMBEDDED_PARSE = '1'; +let unexpectedFetches = 0; +globalThis.fetch = async () => { + unexpectedFetches++; + throw new Error('Unexpected network request in initialization benchmark'); +}; +const headers: Record = { + 'x-vercel-oidc-token': fixture.token, +}; +if (scenario.source === 'header') { + headers['x-vercel-flags-config-versions'] = + `flags_${fixture.projectId}=${fixture.configUpdatedAt}`; +} +const cleanupContext = setRequestContext(headers); + +// Wrap actual source boundaries without changing the production client API. +const originalBundledLoad = BundledSource.prototype.tryLoad; +BundledSource.prototype.tryLoad = function () { + return measure('bundledMs', () => originalBundledLoad.call(this)); +}; +const originalAuthLookup = + Authentication.prototype.resolveBundledDefinitionsLookup; +Authentication.prototype.resolveBundledDefinitionsLookup = function () { + return measure('authLookupMs', () => originalAuthLookup.call(this)); +}; +const originalHeaderCheck = HeaderSource.prototype.isAvailable; +HeaderSource.prototype.isAvailable = function (projectId) { + return measureSync('headerCheckMs', () => + originalHeaderCheck.call(this, projectId), + ); +}; +let startingStream = false; +const originalStreamStart = StreamSource.prototype.start; +StreamSource.prototype.start = function () { + return measure('streamMs', async () => { + startingStream = true; + try { + await originalStreamStart.call(this); + } finally { + startingStream = false; + } + }); +}; +const originalToken = Authentication.prototype.resolveToken; +Authentication.prototype.resolveToken = function () { + return startingStream + ? measure('streamAuthMs', () => originalToken.call(this)) + : originalToken.call(this); +}; + +// The generated parser records only JSON.parse, not console/logging time. +console.info = (label: string, metrics: { durationMs: number }) => { + assert.equal(label, '@vercel/flags-definitions: JSON.parse'); + record('jsonParseMs', metrics.durationMs); +}; + +async function sample(cache: 'cold' | 'warm') { + let streamCalls = 0; + let streamCancelled = false; + let response: Response | undefined; + if (scenario.source === 'stream') { + // Fixture construction is outside all measurements. Do not parse the real + // definitions here: full datafiles are first parsed by the stream decoder. + const wire = scenario.embedded + ? `${JSON.stringify({ + type: 'primed', + revision: fixture.revision, + projectId: fixture.projectId, + environment: 'production', + })}\n` + : readFileSync(new URL('./stream.ndjson', import.meta.url), 'utf8'); + const chunk = new TextEncoder().encode(wire); + response = new Response( + new ReadableStream({ + start(controller) { + controller.enqueue(chunk); + }, + cancel() { + streamCancelled = true; + }, + }), + ); + } + const requests: { url: string; options?: RequestInit }[] = []; + const transport: typeof fetch = async (input, options) => { + streamCalls++; + requests.push({ url: String(input), options }); + if (!response) throw new Error('Unexpected fetch in non-stream scenario'); + return response; + }; + + begin(); + const client = measureSync('createClientMs', () => + createClient(scenario.auth === 'sdk-key' ? fixture.sdkKey : undefined, { + buildStep: false, + stream: scenario.source !== 'offline', + polling: false, + disableMetrics: true, + fetch: transport, + }), + ); + try { + await measure('initializeMs', () => client.initialize()); + const { timings, calls } = finish(); + const start = performance.now(); + await client.initialize(); + const sameClientInitMs = performance.now() - start; + const datafile = await client.getDatafile(); + assert.equal( + datafile.metrics.mode, + scenario.source === 'header' + ? 'vercel' + : scenario.source === 'stream' + ? 'streaming' + : 'offline', + ); + assert.equal(Object.keys(datafile.definitions).length, fixture.flagCount); + assert.equal(streamCalls, scenario.source === 'stream' ? 1 : 0); + for (const request of requests) { + assert.equal(request.url, 'https://flags.vercel.com/v1/stream'); + const requestHeaders = new Headers(request.options?.headers); + assert.equal( + requestHeaders.get('authorization'), + `Bearer ${scenario.auth === 'sdk-key' ? fixture.sdkKey : fixture.token}`, + ); + assert.equal( + requestHeaders.get('x-revision'), + scenario.embedded ? String(fixture.revision) : null, + ); + } + assert.equal(calls.bundledMs, 1); + assert.equal(calls.bundleImportMs, 1); + assert.equal(calls.authLookupMs, 1); + assert.equal(calls.sdkKeyHashMs, scenario.auth === 'sdk-key' ? 1 : 0); + assert.equal( + calls.jsonParseMs, + scenario.embedded && cache === 'cold' ? 1 : 0, + ); + assert.equal(calls.headerCheckMs, scenario.embedded ? 1 : 0); + assert.equal(calls.streamMs, scenario.source === 'stream' ? 1 : 0); + assert.equal(calls.streamAuthMs, scenario.source === 'stream' ? 1 : 0); + assert.equal(unexpectedFetches, 0); + for (const duration of Object.values(timings)) { + assert.ok(Number.isFinite(duration) && duration >= 0); + } + const attributed = + timings.bundleImportMs + + timings.authLookupMs + + timings.sdkKeyHashMs + + timings.jsonParseMs + + timings.headerCheckMs + + timings.streamMs; + return { + cache, + timings: { + ...timings, + otherInitMs: Math.max(0, timings.initializeMs - attributed), + sameClientInitMs, + }, + streamCalls, + calls, + }; + } finally { + finish(); + await client.shutdown(); + await setImmediate(); + assert.equal(streamCancelled, scenario.source === 'stream'); + } +} + +async function main() { + try { + const cold = await sample('cold'); + // A new client in the same process reuses the imported definitions, parsed + // datafile, SDK-key hash promise, and OIDC helper modules from the cold sample. + const warm = await sample('warm'); + console.log(JSON.stringify({ cold, warm })); + } finally { + cleanupContext(); + } +} + +void main().catch((error) => { + console.error(error); + process.exitCode = 1; +}); diff --git a/packages/vercel-flags-core/bench/init.mjs b/packages/vercel-flags-core/bench/init.mjs new file mode 100644 index 00000000..4bc93175 --- /dev/null +++ b/packages/vercel-flags-core/bench/init.mjs @@ -0,0 +1,266 @@ +import assert from 'node:assert/strict'; +import { spawnSync } from 'node:child_process'; +import { mkdir, mkdtemp, readFile, rm, writeFile } from 'node:fs/promises'; +import { cpus } from 'node:os'; +import { dirname, join } from 'node:path'; +import { fileURLToPath, pathToFileURL } from 'node:url'; +import { parseArgs } from 'node:util'; +import { build } from 'tsup'; + +const { values } = parseArgs({ + options: { + definitions: { type: 'string' }, + samples: { type: 'string', default: '10' }, + json: { type: 'boolean', default: false }, + }, +}); +const sampleCount = Number(values.samples); +assert.ok( + Number.isInteger(sampleCount) && sampleCount > 0 && sampleCount <= 100, + '--samples must be an integer between 1 and 100', +); +const root = dirname(dirname(fileURLToPath(import.meta.url))); +const projectId = 'prj_init_benchmark'; +const sdkKey = 'vf_server_init_benchmark'; +const configUpdatedAt = 1_700_000_000_000; +const input = values.definitions + ? JSON.parse(await readFile(values.definitions, 'utf8')) + : { + definitions: Object.fromEntries( + Array.from({ length: 31 }, (_, index) => [ + `benchmark-${index}`, + { environments: { production: 1 }, variants: [false, true] }, + ]), + ), + }; +assert.ok( + input && + typeof input === 'object' && + input.definitions && + typeof input.definitions === 'object' && + !Array.isArray(input.definitions), + 'Expected a datafile with a definitions object', +); +// Preserve flag/segment payloads, but never use project IDs or credentials from +// the supplied file. Stable metadata makes header and priming assertions exact. +const datafile = { + ...input, + projectId, + environment: 'production', + configUpdatedAt, + revision: 1, + digest: 'benchmark', +}; +const scenarios = ['sdk-key', 'oidc'].flatMap((auth) => [ + { name: `${auth}/embedded-only`, auth, source: 'offline', embedded: true }, + { name: `${auth}/version-header`, auth, source: 'header', embedded: true }, + { name: `${auth}/stream-primed`, auth, source: 'stream', embedded: true }, + { name: `${auth}/stream-datafile`, auth, source: 'stream', embedded: false }, +]); + +const cacheDir = join(root, 'node_modules', '.cache'); +await mkdir(cacheDir, { recursive: true }); +const temp = await mkdtemp(join(cacheDir, 'flags-init-bench-')); +try { + const profilePath = join(root, 'bench', 'profile.ts'); + await build({ + entry: { + worker: join(root, 'bench', 'init-worker.ts'), + prepare: join(root, '..', 'prepare-flags-definitions', 'src', 'index.ts'), + }, + outDir: temp, + outExtension: () => ({ js: '.mjs' }), + format: ['esm'], + target: 'node22', + platform: 'node', + config: false, + bundle: true, + splitting: false, + dts: false, + silent: true, + skipNodeModulesBundle: true, + external: ['@vercel/flags-definitions'], + // Probe the two private async boundaries in a TEMPORARY build only. Keep + // source checks strict so a refactor fails rather than silently losing a phase. + esbuildPlugins: [ + { + name: 'init-timing-probes', + setup(esbuild) { + esbuild.onLoad( + { filter: /[/\\]read-bundled-definitions\.ts$/ }, + async ({ path }) => { + let source = await readFile(path, 'utf8'); + const imports = [ + ...source.matchAll(/const module = await import\([\s\S]*?\);/g), + ]; + assert.equal( + imports.length, + 1, + 'Embedded import probe needs updating', + ); + const original = imports[0][0]; + source = source.replace( + original, + original + .replace( + 'await import(', + "await measureInitPhase('bundleImportMs', () => import(", + ) + .replace(/\);$/, '));'), + ); + const hash = 'const hashedKey = await hashSdkKey(lookup.sdkKey);'; + assert.equal( + source.split(hash).length, + 2, + 'SDK key hash probe needs updating', + ); + source = source.replace( + hash, + "const hashedKey = await measureInitPhase('sdkKeyHashMs', () => hashSdkKey(lookup.sdkKey));", + ); + return { + loader: 'ts', + contents: `import { measure as measureInitPhase } from ${JSON.stringify(profilePath)};\n${source}`, + }; + }, + ); + }, + }, + ], + }); + const { generateDefinitionsModule, hashSdkKey } = await import( + pathToFileURL(join(temp, 'prepare.mjs')).href + ); + const token = `e30.${Buffer.from( + JSON.stringify({ + project_id: projectId, + exp: Math.floor(Date.now() / 1000) + 3600, + }), + ).toString('base64url')}.synthetic`; + await writeFile( + join(temp, 'manifest.json'), + JSON.stringify({ + sdkKey, + token, + projectId, + configUpdatedAt, + revision: 1, + flagCount: Object.keys(datafile.definitions).length, + }), + ); + await writeFile( + join(temp, 'stream.ndjson'), + `${JSON.stringify({ type: 'datafile', data: datafile })}\n`, + ); + const moduleDir = join(temp, 'node_modules', '@vercel', 'flags-definitions'); + await mkdir(moduleDir, { recursive: true }); + await writeFile( + join(moduleDir, 'package.json'), + JSON.stringify({ + name: '@vercel/flags-definitions', + type: 'module', + exports: './index.js', + }), + ); + const entries = [ + { key: hashSdkKey(sdkKey), definitions: datafile }, + { key: projectId, definitions: datafile }, + ]; + const rows = []; + for (const scenario of scenarios) { + await writeFile( + join(moduleDir, 'index.js'), + generateDefinitionsModule(scenario.embedded ? entries : [], undefined), + ); + const runs = []; + for (let i = 0; i < sampleCount; i++) { + const child = spawnSync( + process.execPath, + [join(temp, 'worker.mjs'), JSON.stringify(scenario)], + { + encoding: 'utf8', + env: { ...process.env, VERCEL_FLAGS_DEBUG_EMBEDDED_PARSE: '1' }, + }, + ); + if (child.error || child.status !== 0) { + throw new Error( + `Initialization benchmark failed (${scenario.name}): ${child.error?.message ?? child.stderr}`, + ); + } + runs.push(JSON.parse(child.stdout)); + } + for (const cache of ['cold', 'warm']) { + const samples = runs.map((run) => run[cache]); + const metrics = Object.fromEntries( + Object.keys(samples[0].timings).map((phase) => { + const sorted = samples + .map((sample) => sample.timings[phase]) + .sort((a, b) => a - b); + const middle = Math.floor(sorted.length / 2); + return [ + phase, + { + median: + sorted.length % 2 + ? sorted[middle] + : (sorted[middle - 1] + sorted[middle]) / 2, + p95: sorted[Math.ceil(sorted.length * 0.95) - 1], + }, + ]; + }), + ); + rows.push({ + scenario: scenario.name, + cache, + samples: sampleCount, + metrics, + calls: samples[0].calls, + }); + } + } + const report = { + node: process.version, + platform: process.platform, + cpu: cpus()[0]?.model, + datafileBytes: Buffer.byteLength(JSON.stringify(datafile)), + flagCount: Object.keys(datafile.definitions).length, + freshProcesses: scenarios.length * sampleCount, + rows, + }; + if (values.json) { + console.log(JSON.stringify(report)); + } else { + console.log( + `${report.node}, ${report.cpu}: ${report.flagCount} flags / ${report.datafileBytes} bytes; ${report.freshProcesses} fresh processes`, + ); + console.log( + 'Milliseconds; phase columns are medians. Cold = fresh process, warm = new client in the same process.', + ); + console.table( + rows.map(({ scenario, cache, metrics }) => { + const median = (key) => metrics[key].median.toFixed(3); + return { + scenario, + cache, + create: median('createClientMs'), + init: median('initializeMs'), + 'init p95': metrics.initializeMs.p95.toFixed(3), + import: median('bundleImportMs'), + auth: median('authLookupMs'), + hash: median('sdkKeyHashMs'), + JSON: median('jsonParseMs'), + header: median('headerCheckMs'), + stream: median('streamMs'), + other: median('otherInitMs'), + reinit: median('sameClientInitMs'), + }; + }), + ); + console.log( + 'PASS: path, auth, header bypass, memoization, and stream cancellation assertions in every sample. No live network.', + ); + } +} finally { + // This directory is owned by this invocation; supplied files are never modified. + await rm(temp, { recursive: true, force: true }); +} diff --git a/packages/vercel-flags-core/bench/init.test.ts b/packages/vercel-flags-core/bench/init.test.ts new file mode 100644 index 00000000..e1824745 --- /dev/null +++ b/packages/vercel-flags-core/bench/init.test.ts @@ -0,0 +1,95 @@ +import { execFileSync } from 'node:child_process'; +import { fileURLToPath } from 'node:url'; +import { afterEach, describe, expect, it, vi } from 'vitest'; +import { begin, finish, measure, measureSync, record } from './profile'; + +afterEach(() => { + finish(); + vi.restoreAllMocks(); +}); + +describe('initialization performance probes', () => { + it('does not record work outside an initialization sample', async () => { + begin(); + finish(); + await measure('authLookupMs', async () => 'token'); + measureSync('headerCheckMs', () => true); + record('jsonParseMs', 5); + expect(Object.values(finish().calls).every((calls) => calls === 0)).toBe( + true, + ); + }); + + it('records sync and async boundaries, including failures, and resets samples', async () => { + vi.spyOn(performance, 'now') + .mockReturnValueOnce(10) + .mockReturnValueOnce(10.25) + .mockReturnValueOnce(20) + .mockReturnValueOnce(20.5); + begin(); + expect(measureSync('headerCheckMs', () => true)).toBe(true); + await expect( + measure('authLookupMs', async () => { + throw new Error('test failure'); + }), + ).rejects.toThrow('test failure'); + record('jsonParseMs', 0.125); + const result = finish(); + expect(result.timings.headerCheckMs).toBe(0.25); + expect(result.timings.authLookupMs).toBe(0.5); + expect(result.timings.jsonParseMs).toBe(0.125); + expect(result.calls.headerCheckMs).toBe(1); + expect(result.calls.authLookupMs).toBe(1); + expect(result.calls.jsonParseMs).toBe(1); + begin(); + expect( + Object.values(finish().timings).every((duration) => duration === 0), + ).toBe(true); + }); +}); + +it('measures all eight scenarios in isolated processes without latency thresholds', () => { + const stdout = execFileSync( + process.execPath, + [ + fileURLToPath(new URL('./init.mjs', import.meta.url)), + '--samples', + '1', + '--json', + ], + { encoding: 'utf8' }, + ); + const report = JSON.parse(stdout) as { + flagCount: number; + freshProcesses: number; + rows: { + scenario: string; + cache: 'cold' | 'warm'; + samples: number; + metrics: Record; + calls: Record; + }[]; + }; + expect(report.flagCount).toBe(31); + expect(report.freshProcesses).toBe(8); + expect(report.rows).toHaveLength(16); + expect(new Set(report.rows.map((row) => row.scenario)).size).toBe(8); + for (const row of report.rows) { + expect(row.samples).toBe(1); + expect(['cold', 'warm']).toContain(row.cache); + for (const metric of Object.values(row.metrics)) { + expect(Number.isFinite(metric.median)).toBe(true); + expect(metric.median).toBeGreaterThanOrEqual(0); + expect(metric.p95).toBe(metric.median); + } + const stream = row.scenario.includes('/stream-'); + const embedded = !row.scenario.endsWith('/stream-datafile'); + expect(row.calls.streamMs).toBe(stream ? 1 : 0); + expect(row.calls.jsonParseMs).toBe( + row.cache === 'cold' && embedded ? 1 : 0, + ); + expect(row.calls.sdkKeyHashMs).toBe( + row.scenario.startsWith('sdk-key/') ? 1 : 0, + ); + } +}, 30_000); diff --git a/packages/vercel-flags-core/bench/profile.ts b/packages/vercel-flags-core/bench/profile.ts new file mode 100644 index 00000000..a54c12fe --- /dev/null +++ b/packages/vercel-flags-core/bench/profile.ts @@ -0,0 +1,64 @@ +// Benchmark-only probes. These are bundled into the temporary worker, never the SDK. +export const phases = [ + 'createClientMs', + 'initializeMs', + 'bundledMs', + 'bundleImportMs', + 'authLookupMs', + 'sdkKeyHashMs', + 'jsonParseMs', + 'headerCheckMs', + 'streamMs', + 'streamAuthMs', +] as const; + +export type Phase = (typeof phases)[number]; +export type Measurements = Record; + +let active = false; +let timings = empty(); +let calls = empty(); + +function empty(): Measurements { + return Object.fromEntries(phases.map((phase) => [phase, 0])) as Measurements; +} + +export function begin(): void { + timings = empty(); + calls = empty(); + active = true; +} + +export function record(phase: Phase, duration: number): void { + if (!active) return; + timings[phase] += duration; + calls[phase] += 1; +} + +export async function measure( + phase: Phase, + fn: () => T | Promise, +): Promise { + if (!active) return fn(); + const start = performance.now(); + try { + return await fn(); + } finally { + record(phase, performance.now() - start); + } +} + +export function measureSync(phase: Phase, fn: () => T): T { + if (!active) return fn(); + const start = performance.now(); + try { + return fn(); + } finally { + record(phase, performance.now() - start); + } +} + +export function finish() { + active = false; + return { timings: { ...timings }, calls: { ...calls } }; +} diff --git a/packages/vercel-flags-core/package.json b/packages/vercel-flags-core/package.json index b1edb0ae..4d650ebe 100644 --- a/packages/vercel-flags-core/package.json +++ b/packages/vercel-flags-core/package.json @@ -65,6 +65,7 @@ "CHANGELOG.md" ], "scripts": { + "bench:init": "node bench/init.mjs", "build": "tsup", "dev": "tsup --watch", "check": "biome check", diff --git a/packages/vercel-flags-core/tsconfig.json b/packages/vercel-flags-core/tsconfig.json index 1d5db943..9d80ee16 100644 --- a/packages/vercel-flags-core/tsconfig.json +++ b/packages/vercel-flags-core/tsconfig.json @@ -1,6 +1,6 @@ { "extends": "../../tsconfig-base.json", - "include": ["src"], + "include": ["src", "bench/**/*.ts"], "compilerOptions": { "resolveJsonModule": true, "target": "ES2023"