Skip to content

Commit 5d03da0

Browse files
committed
feat(core): emit dev-only pipeline stage timings and surface them in the benchmark
The block-memo path runs four stages per content change (parse → transform → build → render) and every optimization decision should start from that split. measureStage() wraps each stage and emits one performance.measure per execution (ai-markdown:stage:*), so the DevTools Performance panel picks them up with zero wiring and the BlockMemoCompare story's new 'Pipeline stages' panel aggregates avg/Σ/count/max per stage. Design points, each the survivor of a review finding: - PIPELINE_STAGES tuple is the single source of truth: the union type, the emitted names (hoisted table, no per-call allocation), and the panel's display order all derive from it — a new stage cannot be silently omitted from the display. - measureStage(stage, fn) is single-callable: the stage name is a typed argument and the start/end pairing is unforgettable by construction. - The ENABLED gate builds on the shared DEV constant plus a ONE-TIME capability probe of the exact calls made (options-object measure + clearMeasures) — environments with only legacy measure overloads gate off permanently instead of paying a swallowed throw per stage per token. - Entries are cleared from the global User Timing buffer immediately after emission: live observers still receive every entry (delivery is queued at creation) while the buffer never grows from render work — ~4 entries/token in ANY consuming app's dev build, observer or not. Buffer readers (console getEntriesByType, late buffered observers) see nothing by design; documented in docs/streaming-and-performance.md ('Built-in stage timing') together with the always-on-in-dev tradeoff. - Production builds fold ENABLED to false; unbundled Node SSR pays one boolean per stage. Story side: useRenderProfiler gains observeStages (page-wide measures — enabled ONLY on the block-memo side per page to keep attribution honest; IsolatedSide enables it for memo mode).
1 parent 85170f4 commit 5d03da0

7 files changed

Lines changed: 238 additions & 11 deletions

File tree

docs/streaming-and-performance.md

Lines changed: 34 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -205,6 +205,40 @@ If profiling shows `<AIMarkdown>` as the bottleneck:
205205
2. Try `blockMemoEnabled: false` to isolate whether the issue is in memoization or upstream.
206206
3. Profile with React DevTools — a tree with most blocks under "Did not render" is healthy.
207207

208+
### Built-in stage timing (dev builds only)
209+
210+
In development builds, the block-memo render path emits one
211+
[`performance.measure`](https://developer.mozilla.org/docs/Web/API/Performance/measure)
212+
entry per pipeline stage per content change, named:
213+
214+
```
215+
ai-markdown:stage:parse # unified.parse over the full document
216+
ai-markdown:stage:transform # remark/rehype transformer run
217+
ai-markdown:stage:build # block-plan construction
218+
ai-markdown:stage:render # per-block render with cache lookup
219+
```
220+
221+
This is how to answer "which stage eats the budget" without guessing —
222+
the numbers map 1:1 onto the (1)/(2)/(3) split above. Two supported ways
223+
to read them:
224+
225+
- **DevTools Performance panel**: record a session; the measures appear in
226+
the User Timing track. No wiring needed — emission is always on in dev,
227+
which is a deliberate choice traded against a few `performance.*` calls
228+
per token.
229+
- **A live `PerformanceObserver`** for `entryTypes: ['measure']`, filtering
230+
by the `ai-markdown:stage:` prefix (the built-in Storybook benchmark's
231+
"Pipeline stages" panel does exactly this).
232+
233+
Delivery semantics to know before wiring your own reader: each entry is
234+
**cleared from the global User Timing buffer immediately after emission**,
235+
so the buffer never grows from render work. Already-registered observers
236+
still receive every entry (delivery is queued at creation), but
237+
`performance.getEntriesByType('measure')` from the console and
238+
late-attached `buffered: true` observers will see nothing — attach your
239+
observer before streaming starts. Production builds emit nothing and pay
240+
one boolean check per stage.
241+
208242
### Validating output equivalence
209243

210244
If you suspect `blockMemoEnabled: true` is producing different output than `false`, the library's test suite includes a `byteEquivalence.test.tsx` harness that asserts byte-identical HTML across every plugin permutation. Failures should be reported as bugs.

packages/core/src/components/MarkdownContent.tsx

Lines changed: 23 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -65,6 +65,7 @@ import remarkSmartypants from 'remark-smartypants';
6565
import remarkPangu from 'remark-pangu';
6666
import remarkRemoveComments from 'remark-remove-comments';
6767
import { buildBlocks, createCache, renderBlocksWithCache, type Cache, type PostOptions } from './blockMemo';
68+
import { measureStage } from './devStageTimings';
6869
import { useAIMarkdownRenderState } from '../context';
6970
import {
7071
AIMarkdownCustomComponents,
@@ -440,12 +441,17 @@ const BlockMemoizedRenderer = memo(
440441
: {
441442
...remarkRehypeOptions,
442443
};
443-
return parseStage({
444-
children: augmented,
445-
remarkPlugins,
446-
rehypePlugins,
447-
remarkRehypeOptions: mergedRemarkRehypeOptions as RemarkRehypeOptions,
448-
});
444+
// Dev-only stage telemetry (`ai-markdown:stage:*` performance
445+
// measures; no-op in production). Wraps only the stage call — the
446+
// surrounding option assembly is trivial.
447+
return measureStage('parse', () =>
448+
parseStage({
449+
children: augmented,
450+
remarkPlugins,
451+
rehypePlugins,
452+
remarkRehypeOptions: mergedRemarkRehypeOptions as RemarkRehypeOptions,
453+
})
454+
);
449455
}, [
450456
content,
451457
targetPhantoms,
@@ -456,11 +462,14 @@ const BlockMemoizedRenderer = memo(
456462
preserveForBodyHarvest,
457463
documentId,
458464
]);
459-
const hast = useMemo(() => transformStage(parsed), [parsed]);
465+
const hast = useMemo(() => measureStage('transform', () => transformStage(parsed)), [parsed]);
460466

461467
// Cut hast into per-block units indexed back to mdast for cache identity,
462468
// and compute the document-wide ctx digest for cross-block invalidation.
463-
const built = useMemo(() => buildBlocks(parsed.mdast, hast, content ?? ''), [parsed.mdast, hast, content]);
469+
const built = useMemo(
470+
() => measureStage('build', () => buildBlocks(parsed.mdast, hast, content ?? '')),
471+
[parsed.mdast, hast, content]
472+
);
464473

465474
const postOptions = useMemo<PostOptions>(
466475
() => ({
@@ -613,7 +622,12 @@ const BlockMemoizedRenderer = memo(
613622
}, [parsed, ownLabels, registry, targetPhantoms, sym, hast, clobberPrefix, urlTransform]);
614623

615624
// Intentional cache memoization via cacheRef; see G3 comment above.
616-
const rendered = renderBlocksWithCache(cacheRef, built.plan, built.globalCtx, postOptions);
625+
// Unlike the three memoized stages above, this runs on EVERY render —
626+
// its 'render' measures therefore include the cheap all-cache-hit
627+
// re-renders, which is the honest shape of what block-memo saves.
628+
const rendered = measureStage('render', () =>
629+
renderBlocksWithCache(cacheRef, built.plan, built.globalCtx, postOptions)
630+
);
617631

618632
// Cross-chunk URL sanitization policy — read by `CrossChunkLink` and
619633
// `CrossChunkImage` at render time to apply the same two-gate pipeline
Lines changed: 94 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,94 @@
1+
/**
2+
* Dev-only pipeline stage timing.
3+
*
4+
* The block-memo render path runs four distinct stages per content change
5+
* (parse → transform → build → render). Which one dominates depends on the
6+
* workload — plugin mix, document length, math density — and every
7+
* optimization decision should start from that split, not from a guess.
8+
* {@link measureStage} emits one `performance.measure` entry per stage
9+
* execution, named `ai-markdown:stage:<stage>`, so any live
10+
* PerformanceObserver (the DevTools Performance panel's tracing, the
11+
* BlockMemoCompare story's profiler) can aggregate them without the
12+
* library depending on the observer.
13+
*
14+
* Delivery contract: entries are cleared from the global User Timing
15+
* buffer immediately after emission — already-registered observers still
16+
* receive them (delivery is queued at creation), but buffer readers
17+
* (`performance.getEntriesByType('measure')` in the console, late
18+
* `buffered: true` observers) see nothing. That is the price of never
19+
* growing the page-global buffer from a render hot path (~4 entries per
20+
* streamed token, observer or not). The DevTools Performance panel is
21+
* unaffected — it captures measures from the trace, not the buffer.
22+
*
23+
* Production builds fold {@link ENABLED} to `false` (bundler substitution
24+
* via the shared `DEV` gate) and the whole thing costs one boolean check
25+
* per stage; unbundled Node SSR pays the same boolean, evaluated from an
26+
* env read done once at import.
27+
*
28+
* @module components/devStageTimings
29+
*/
30+
31+
import { DEV } from '../devEnv';
32+
33+
/** The stages of the block-memo render pipeline, in execution order.
34+
* Single source of truth: the union type, the emitted measure names, and
35+
* any display ordering (ProfilerPanel) all derive from this tuple. */
36+
export const PIPELINE_STAGES = ['parse', 'transform', 'build', 'render'] as const;
37+
export type PipelineStage = (typeof PIPELINE_STAGES)[number];
38+
39+
/** Prefix for the emitted `performance.measure` entry names. */
40+
export const STAGE_MEASURE_PREFIX = 'ai-markdown:stage:';
41+
42+
/** Hoisted name table — measure names are shared constants, not a fresh
43+
* template-literal allocation per call. */
44+
const STAGE_NAMES = Object.fromEntries(
45+
PIPELINE_STAGES.map((stage) => [stage, `${STAGE_MEASURE_PREFIX}${stage}`])
46+
) as Record<PipelineStage, string>;
47+
48+
/**
49+
* One-time capability gate. Beyond the DEV check, probes the exact calls
50+
* {@link measureStage} makes — the options-object `measure` overload AND
51+
* `clearMeasures` — by performing them once. Environments that expose
52+
* `performance.measure` but only support the legacy mark-name overloads
53+
* (older jsdom, partial polyfills) fail the probe and are gated off
54+
* permanently, instead of paying a thrown-and-swallowed exception per
55+
* stage per token for the whole session.
56+
*/
57+
const ENABLED: boolean =
58+
DEV &&
59+
(() => {
60+
if (
61+
typeof performance === 'undefined' ||
62+
typeof performance.measure !== 'function' ||
63+
typeof performance.clearMeasures !== 'function'
64+
) {
65+
return false;
66+
}
67+
try {
68+
const probe = `${STAGE_MEASURE_PREFIX}probe`;
69+
performance.measure(probe, { start: 0, end: 0 });
70+
performance.clearMeasures(probe);
71+
return true;
72+
} catch {
73+
return false;
74+
}
75+
})();
76+
77+
/**
78+
* Run `fn` as the named pipeline stage, emitting its `performance.measure`
79+
* in dev. The single-callable shape (instead of a start/end pair) makes
80+
* the stage name a typed argument and the pairing unforgettable: a call
81+
* site cannot mismatch or drop an end call. If `fn` throws, no measure is
82+
* emitted for the aborted stage.
83+
*/
84+
export function measureStage<T>(stage: PipelineStage, fn: () => T): T {
85+
if (!ENABLED) return fn();
86+
const start = performance.now();
87+
const result = fn();
88+
const name = STAGE_NAMES[stage];
89+
// Probe-verified calls — no per-call try/catch needed. See the module
90+
// docs for why the entry is cleared immediately after emission.
91+
performance.measure(name, { start, end: performance.now() });
92+
performance.clearMeasures(name);
93+
return result;
94+
}

packages/core/stories/streaming/BlockMemoComparison.tsx

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -114,7 +114,10 @@ export const BlockMemoComparison = ({
114114
const payloadBlocks = useMemo(() => countBlocks(effectivePayload), [effectivePayload]);
115115
const scenarios = useMemo(() => buildScenarios(effectivePayload), [effectivePayload]);
116116

117-
const enabledProfiler = useRenderProfiler<HTMLDivElement>({ running });
117+
// observeStages on the ENABLED side only: the stage measures are
118+
// page-wide and only the block-memo path emits them — observing on both
119+
// would print the same union under the legacy panel.
120+
const enabledProfiler = useRenderProfiler<HTMLDivElement>({ running, observeStages: true });
118121
const disabledProfiler = useRenderProfiler<HTMLDivElement>({ running });
119122
const theme = getStreamingTheme(colorScheme);
120123

packages/core/stories/streaming/IsolatedSide.tsx

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -46,7 +46,7 @@ export const IsolatedSide = () => {
4646
// property chains on a hook result that contains refs as ref accesses
4747
// during render; plain bindings keep the analyzer satisfied.
4848
const { snapshot, onRender, targetRef, recordChunk, recordElementRender, reset } =
49-
useRenderProfiler<HTMLDivElement>({ running });
49+
useRenderProfiler<HTMLDivElement>({ running, observeStages: mode === 'memo' });
5050
const theme = getStreamingTheme(scheme);
5151

5252
// Slim the iframe's own viewport scrollbar too (the side page can be

packages/core/stories/streaming/ProfilerPanel.tsx

Lines changed: 26 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,7 @@
11
'use client';
22

33
import type { CSSProperties, ReactNode } from 'react';
4+
import { PIPELINE_STAGES } from '../../src/components/devStageTimings';
45
import type { RenderProfilerSnapshot } from './useRenderProfiler';
56
import { getStreamingTheme, type ColorScheme } from './theme';
67

@@ -13,6 +14,16 @@ function topTags(byTag: Record<string, number>, limit: number): Array<[string, n
1314
.slice(0, limit);
1415
}
1516

17+
/** Panel fields for the observed pipeline stages, in pipeline order. Empty
18+
* when this profiler doesn't observe stage measures (legacy side). */
19+
function stageFields(snapshot: RenderProfilerSnapshot): Field[] {
20+
return PIPELINE_STAGES.filter((k) => snapshot.stages[k]).map((k) => ({
21+
label: `${k} avg (ms)`,
22+
value: fmt(snapshot.stages[k].total / snapshot.stages[k].count),
23+
sub: ${fmt(snapshot.stages[k].total, 0)} ms · ×${snapshot.stages[k].count} · max ${fmt(snapshot.stages[k].max, 1)}`,
24+
}));
25+
}
26+
1627
type Tone = 'good' | 'warn' | 'bad';
1728

1829
interface Field {
@@ -40,6 +51,7 @@ export const ProfilerPanel = ({
4051
compact?: boolean;
4152
}) => {
4253
const theme = getStreamingTheme(colorScheme);
54+
const stages = stageFields(snapshot);
4355

4456
const sectionStyle: CSSProperties = {
4557
background: theme.panelBg,
@@ -127,6 +139,20 @@ export const ProfilerPanel = ({
127139
{ label: 'max base (ms)', value: fmt(snapshot.base.max) },
128140
],
129141
},
142+
// Pipeline stage timings — present only when this profiler observes the
143+
// dev-only `ai-markdown:stage:*` measures (block-memo side). Ordered by
144+
// the shared PIPELINE_STAGES tuple so a stage added to the pipeline
145+
// cannot be silently omitted from the panel.
146+
...(stages.length === 0
147+
? []
148+
: [
149+
{
150+
title: 'Pipeline stages (dev-only)',
151+
hint:
152+
'per-execution timings from ai-markdown:stage:* performance measures, emitted by the block-memo path only. parse + transform run on every content change regardless of caching — they are the incremental-parse opportunity; render is where block-memo saves. render also fires on cache-hit-only re-renders, so its avg skews low by design.',
153+
fields: stages,
154+
},
155+
]),
130156
{
131157
title: 'Component renders',
132158
hint: 'spy customComponents count function-body invocations per tag (react-scan-style). Block-memo skips re-invoking components inside cached subtrees → totals diverge cleanly between paths.',

packages/core/stories/streaming/useRenderProfiler.ts

Lines changed: 56 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -35,6 +35,7 @@
3535

3636
import { useCallback, useEffect, useRef, useState } from 'react';
3737
import type { ProfilerOnRenderCallback, RefObject } from 'react';
38+
import { STAGE_MEASURE_PREFIX } from '../../src/components/devStageTimings';
3839

3940
export interface ChunkSample {
4041
index: number;
@@ -86,6 +87,13 @@ export interface ElementRenderStats {
8687
byTag: Record<string, number>;
8788
}
8889

90+
/** Aggregate of one pipeline stage's `performance.measure` entries. */
91+
export interface StageStats {
92+
count: number;
93+
total: number;
94+
max: number;
95+
}
96+
8997
export interface RenderProfilerSnapshot {
9098
/** Commits intentionally excluded from stats during JIT warm-up. */
9199
warmUpCommits: number;
@@ -117,6 +125,14 @@ export interface RenderProfilerSnapshot {
117125
* component level" — react-scan-style without DevTools hook hackery.
118126
*/
119127
elementRenders: ElementRenderStats;
128+
/**
129+
* Dev-only pipeline stage timings (`ai-markdown:stage:*` performance
130+
* measures emitted by the block-memo render path). Empty unless the hook
131+
* was created with `observeStages: true` AND an instrumented (dev-build,
132+
* block-memo) renderer is measuring on this page. Keyed by stage name
133+
* (parse / transform / build / render).
134+
*/
135+
stages: Record<string, StageStats>;
120136
chunks: ChunkSample[];
121137
totalChars: number;
122138
lastResetAt: number;
@@ -142,6 +158,13 @@ export interface RenderProfilerOptions {
142158
* task after the stream ends is still captured.
143159
*/
144160
running?: boolean;
161+
/**
162+
* Aggregate `ai-markdown:stage:*` performance measures into
163+
* `snapshot.stages`. Measures are PAGE-WIDE — in a same-page comparison
164+
* only ONE profiler (the block-memo side's) should observe them, or both
165+
* panels would display the same union. Default `false`.
166+
*/
167+
observeStages?: boolean;
145168
}
146169

147170
export interface RenderProfilerHandle<T extends HTMLElement = HTMLElement> {
@@ -203,6 +226,7 @@ export const emptySnapshot = (): RenderProfilerSnapshot => ({
203226
rafCount: 0,
204227
longTasks: emptyLongTasks(),
205228
elementRenders: emptyElementRenders(),
229+
stages: {},
206230
chunks: [],
207231
totalChars: 0,
208232
lastResetAt: 0,
@@ -244,6 +268,8 @@ interface Accum {
244268
// Element render counter (driven by spy customComponents)
245269
elementRenderTotal: number;
246270
elementRenderByTag: Record<string, number>;
271+
// Pipeline stage measures (observeStages only)
272+
stages: Record<string, StageStats>;
247273
// Stream chunks
248274
chunks: ChunkSample[];
249275
totalChars: number;
@@ -279,6 +305,7 @@ const emptyAccum = (now: number): Accum => ({
279305
longTaskMax: 0,
280306
elementRenderTotal: 0,
281307
elementRenderByTag: {},
308+
stages: {},
282309
chunks: [],
283310
totalChars: 0,
284311
lastResetAt: now,
@@ -329,6 +356,7 @@ export function useRenderProfiler<T extends HTMLElement = HTMLElement>(
329356
const maxSamples = opts?.maxSamples ?? 500;
330357
const snapshotMs = opts?.snapshotIntervalMs ?? 100;
331358
const running = opts?.running ?? true;
359+
const observeStages = opts?.observeStages ?? false;
332360

333361
// Lazy initialization to avoid calling `performance.now()` during render
334362
// (would trip React Compiler purity checks).
@@ -465,6 +493,7 @@ export function useRenderProfiler<T extends HTMLElement = HTMLElement>(
465493
total: acc.elementRenderTotal,
466494
byTag: { ...acc.elementRenderByTag },
467495
},
496+
stages: Object.fromEntries(Object.entries(acc.stages).map(([k, v]) => [k, { ...v }])),
468497
chunks: acc.chunks.slice(),
469498
totalChars: acc.totalChars,
470499
lastResetAt: acc.lastResetAt,
@@ -549,6 +578,33 @@ export function useRenderProfiler<T extends HTMLElement = HTMLElement>(
549578
return () => obs.disconnect();
550579
}, []);
551580

581+
// PerformanceObserver measure — aggregates the dev-only pipeline stage
582+
// timings the block-memo renderer emits (see src devStageTimings).
583+
// Page-wide by nature; only enable on ONE profiler per page (the
584+
// block-memo side), otherwise both panels show the same union.
585+
useEffect(() => {
586+
if (!observeStages || typeof PerformanceObserver === 'undefined') return;
587+
let observer: PerformanceObserver | undefined;
588+
try {
589+
observer = new PerformanceObserver((list) => {
590+
const acc = accumRef.current;
591+
if (!acc) return;
592+
for (const entry of list.getEntries()) {
593+
if (!entry.name.startsWith(STAGE_MEASURE_PREFIX)) continue;
594+
const stage = entry.name.slice(STAGE_MEASURE_PREFIX.length);
595+
const s = (acc.stages[stage] ??= { count: 0, total: 0, max: 0 });
596+
s.count += 1;
597+
s.total += entry.duration;
598+
if (entry.duration > s.max) s.max = entry.duration;
599+
}
600+
});
601+
observer.observe({ entryTypes: ['measure'] });
602+
} catch {
603+
// measure observation unsupported — stage panel simply stays empty.
604+
}
605+
return () => observer?.disconnect();
606+
}, [observeStages]);
607+
552608
// PerformanceObserver longtask — main-thread blocks ≥ 50 ms, the kind
553609
// that produce visible jank. Page-wide (not per-side), so when two
554610
// profilers run in the same tab they will report identical numbers. Use

0 commit comments

Comments
 (0)