test(flags-core): profile initialization across auth and source modes

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)

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<string, unknown> | 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,

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 = { "<sha256_hash>": _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

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`: