vercel/next.js · #99322
Scope client component loading metrics to HTML renders
packages/next/src/server/app-render/app-render.tsx195 + / 120 −
@@ -210,7 +210,7 @@ import { } from './dynamic-rendering' import { logBuildDebugHint } from './blocking-route-messages' import {- getClientComponentLoaderMetrics,+ ClientComponentLoadTracker, wrapClientComponentLoader, } from '../client-component-renderer-logger' import { isNodeNextRequest, isNodeNextResponse } from '../base-http/helpers'@@ -2586,18 +2586,17 @@ export type BinaryStreamOf<T> = AnyStream /** * Extracted to a separate function to prevent V8 from retaining the entire- * `prepareAppPageRender` closure scope through globalThis.__next_require__.+ * the render initialization scope through globalThis.__next_require__. * V8 shares a single Context object per scope for all closures; by creating * these closures in their own function scope, the globalThis references only * retain `instrumented` and `cacheComponents`, not request-specific data like * req/res/workStore. */ function installGlobalModuleLoadingHandlers( ComponentMod: AppPageModule,- cacheComponents: boolean,- isTracingEnabled: boolean+ cacheComponents: boolean ) {- const instrumented = wrapClientComponentLoader(ComponentMod, isTracingEnabled)+ const instrumented = wrapClientComponentLoader(ComponentMod) // When we are prerendering if there is a cacheSignal for tracking // cache reads we track calls to `loadChunk` and `require`. This allows us@@ -2682,6 +2681,55 @@ const generatePrerenderRequestId: GenerateRequestId = async (req) => { ).toString('hex') } +function initializeClientComponentLoadTracking(+ renderOpts: RenderOpts,+ workStore: WorkStore+): ClientComponentLoadTracker | undefined {+ if (!renderOpts.ComponentMod.__next_app__) return undefined++ // Capture the request's span before the HTML render creates its own span.+ const parentSpan = getTracer().getActiveScopeSpan()+ const isTracingEnabled = parentSpan?.isRecording() ?? false++ let tracker: ClientComponentLoadTracker | undefined+ if (+ 'performance' in globalThis &&+ (process.env.NEXT_OTEL_PERFORMANCE_PREFIX || isTracingEnabled)+ ) {+ tracker = new ClientComponentLoadTracker((metrics) => {+ if (+ process.env.NEXT_RUNTIME !== 'edge' &&+ isTracingEnabled &&+ metrics &&+ metrics.clientComponentLoadEnd >= metrics.clientComponentLoadStart+ ) {+ getTracer()+ .startSpan(NextNodeServerSpan.clientComponentLoading, {+ parentSpan,+ startTime: metrics.clientComponentLoadStart,+ attributes: {+ 'next.clientComponentLoadCount': metrics.clientComponentLoadCount,+ 'next.span_type': NextNodeServerSpan.clientComponentLoading,+ },+ })+ .end(metrics.clientComponentLoadEnd)+ }+ })+ workStore.clientComponentLoadTracker = tracker+ }+ return tracker+}++function finishClientComponentLoadTrackingOnReady(+ tracker: ClientComponentLoadTracker | undefined,+ allReady: Promise<unknown>+) {+ if (tracker) {+ const finish = () => tracker.finish()+ void allReady.then(finish, finish)+ }+}+ async function prepareAppPageRender( req: BaseNextRequest, res: BaseNextResponse,@@ -2719,18 +2767,6 @@ async function prepareAppPageRender( setIsrStatus, } = renderOpts - // We need to expose the bundled `require` API globally for- // react-server-dom-webpack. This is a hack until we find a better way.- if (ComponentMod.__next_app__) {- const isTracingEnabled =- getTracer().getActiveScopeSpan()?.isRecording() ?? false- installGlobalModuleLoadingHandlers(- ComponentMod,- cacheComponents,- isTracingEnabled- )- }- if (process.env.__NEXT_DEV_SERVER && setIsrStatus && !cacheComponents) { // Reset the ISR status at start of request. const { pathname } = new URL(req.url || '/', 'http://n')@@ -2752,27 +2788,6 @@ async function prepareAppPageRender( // report them at that time. workStore.shouldTrackFetchMetrics = false })-- req.originalRequest.on('end', () => {- if ('performance' in globalThis) {- const metrics = getClientComponentLoaderMetrics({ reset: true })- if (- metrics &&- metrics.clientComponentLoadEnd >= metrics.clientComponentLoadStart- ) {- getTracer()- .startSpan(NextNodeServerSpan.clientComponentLoading, {- startTime: metrics.clientComponentLoadStart,- attributes: {- 'next.clientComponentLoadCount':- metrics.clientComponentLoadCount,- 'next.span_type': NextNodeServerSpan.clientComponentLoading,- },- })- .end(metrics.clientComponentLoadEnd)- }- }- }) } const metadata: AppPageRenderResultMetadata = {@@ -2910,14 +2925,21 @@ async function prerenderAppPage({ prerenderToStream ) - const response = await prerenderToStreamWithTracing(- req,- res,- ctx,- metadata,- loaderTree,- fallbackRouteParams- )+ const tracker = initializeClientComponentLoadTracking(renderOpts, workStore)+ metadata.clientComponentLoadTracker = tracker+ let response: PrerenderToStreamResult+ try {+ response = await prerenderToStreamWithTracing(+ req,+ res,+ ctx,+ metadata,+ loaderTree,+ fallbackRouteParams+ )+ } finally {+ tracker?.finish()+ } // If we're debugging partial prerendering, print all the dynamic API accesses // that occurred during the render.@@ -3141,7 +3163,12 @@ async function renderAppPage( ) } else { // MARK: RSC dynamic- return generateDynamicFlightRenderResult(req, ctx, requestStore)+ return generateDynamicFlightRenderResult(+ req,+ ctx,+ requestStore,+ undefined+ ) } } }@@ -3167,23 +3194,35 @@ async function renderAppPage( const notFoundLoaderTree = createNotFoundLoaderTree(loaderTree) res.statusCode = 404 metadata.statusCode = 404- const stream = await renderToStream(- requestStore,- req,- res,- ctx,- notFoundLoaderTree,- formState,- postponedState,- metadata,- undefined, // Prevent restartable-render behavior in dev + Cache Components mode- stagedFallbackParams+ const tracker = initializeClientComponentLoadTracking(+ renderOpts,+ workStore )+ metadata.clientComponentLoadTracker = tracker+ try {+ const stream = await renderToStream(+ requestStore,+ req,+ res,+ ctx,+ notFoundLoaderTree,+ formState,+ postponedState,+ metadata,+ undefined, // Prevent restartable-render behavior in dev + Cache Components mode+ stagedFallbackParams,+ tracker+ ) - return new RenderResult(stream, {- metadata,- contentType: HTML_CONTENT_TYPE_HEADER,- })+ return new RenderResult(stream, {+ metadata,+ contentType: HTML_CONTENT_TYPE_HEADER,+ })+ } catch (renderError) {+ // Failed setup may never reach the SSR readiness callback.+ tracker?.finish()+ throw renderError+ } } else if (actionRequestResult.type === 'done') { if (actionRequestResult.result) { actionRequestResult.result.assignMetadata(metadata)@@ -3202,66 +3241,76 @@ async function renderAppPage( contentType: HTML_CONTENT_TYPE_HEADER, } - const stream = await renderToStream(- // NOTE: in Cache Components (dev), if the render is restarted, it will use a different requestStore- // than the one that we're passing in here.- requestStore,- req,- res,- ctx,- loaderTree,- formState,- postponedState,- metadata,- // If we're rendering HTML after an action, we don't want restartable-render behavior- // because the result should be dynamic, like it is in prod.- // Also, the request store might have been mutated by the action (e.g. enabling draftMode)- // and we currently we don't copy changes over when creating a new store,- // so the restarted render wouldn't be correct.- didExecuteServerAction ? undefined : createRequestStore,- stagedFallbackParams- )-- // Forward an invalid-dynamic-usage error recorded by `'use cache'` only- // when userland caught it (try/catch around the cache call). If userland- // didn't catch, the rejection propagated into the React render, and React's- // `serverComponentsErrorHandler` already stamped a digest on the error and- // emitted it as a Flight error chunk — surfacing it again here would- // duplicate the entry in the dev overlay.- //- // The cacheComponents paths forward this themselves via- // `runValidationInDev` and the validation-skipped fallback in- // `generateDynamicFlightRenderResultWithStagesInDev`. Here we cover the- // non-cacheComponents dev path where neither runs.- if (- process.env.__NEXT_DEV_SERVER &&- !cacheComponents &&- workStore.invalidDynamicUsageError &&- !(workStore.invalidDynamicUsageError as { digest?: unknown }).digest- ) {- void logMessagesAndSendErrorsToBrowser(- [workStore.invalidDynamicUsageError],- ctx+ const tracker = initializeClientComponentLoadTracking(renderOpts, workStore)+ metadata.clientComponentLoadTracker = tracker+ try {+ const stream = await renderToStream(+ // NOTE: in Cache Components (dev), if the render is restarted, it will use a different requestStore+ // than the one that we're passing in here.+ requestStore,+ req,+ res,+ ctx,+ loaderTree,+ formState,+ postponedState,+ metadata,+ // If we're rendering HTML after an action, we don't want restartable-render behavior+ // because the result should be dynamic, like it is in prod.+ // Also, the request store might have been mutated by the action (e.g. enabling draftMode)+ // and we currently we don't copy changes over when creating a new store,+ // so the restarted render wouldn't be correct.+ didExecuteServerAction ? undefined : createRequestStore,+ stagedFallbackParams,+ tracker )- } - // If we have pending revalidates, wait until they are all resolved.- const maybeRevalidatesPromise = executeRevalidates(workStore)- if (maybeRevalidatesPromise !== false) {- const revalidatesPromise = maybeRevalidatesPromise.finally(() => {- if (process.env.NEXT_PRIVATE_DEBUG_CACHE) {- console.log('pending revalidates promise finished for:', url.href)+ // Forward an invalid-dynamic-usage error recorded by `'use cache'` only+ // when userland caught it (try/catch around the cache call). If userland+ // didn't catch, the rejection propagated into the React render, and React's+ // `serverComponentsErrorHandler` already stamped a digest on the error and+ // emitted it as a Flight error chunk — surfacing it again here would+ // duplicate the entry in the dev overlay.+ //+ // The cacheComponents paths forward this themselves via+ // `runValidationInDev` and the validation-skipped fallback in+ // `generateDynamicFlightRenderResultWithStagesInDev`. Here we cover the+ // non-cacheComponents dev path where neither runs.+ if (+ process.env.__NEXT_DEV_SERVER &&+ !cacheComponents &&+ workStore.invalidDynamicUsageError &&+ !(workStore.invalidDynamicUsageError as { digest?: unknown }).digest+ ) {+ void logMessagesAndSendErrorsToBrowser(+ [workStore.invalidDynamicUsageError],+ ctx+ )+ }++ // If we have pending revalidates, wait until they are all resolved.+ const maybeRevalidatesPromise = executeRevalidates(workStore)+ if (maybeRevalidatesPromise !== false) {+ const revalidatesPromise = maybeRevalidatesPromise.finally(() => {+ if (process.env.NEXT_PRIVATE_DEBUG_CACHE) {+ console.log('pending revalidates promise finished for:', url.href)+ }+ })+ if (renderOpts.waitUntil) {+ renderOpts.waitUntil(revalidatesPromise)+ } else {+ options.waitUntil = revalidatesPromise }- })- if (renderOpts.waitUntil) {- renderOpts.waitUntil(revalidatesPromise)- } else {- options.waitUntil = revalidatesPromise }- } - // Create the new render result for the response.- return new RenderResult(stream, options)+ // Create the new render result for the response.+ return new RenderResult(stream, options)+ } catch (renderError) {+ // Returning a stream may precede SSR readiness, which finishes success.+ // Only failures finish here; a finally would seal successful renders early.+ tracker?.finish()+ throw renderError+ } } async function renderToHTMLOrFlightImpl(@@ -3280,6 +3329,12 @@ async function renderToHTMLOrFlightImpl( fallbackRouteParams: OpaqueFallbackRouteParams | null, routeMatch: RouteMatch ) {+ if (renderOpts.ComponentMod.__next_app__) {+ installGlobalModuleLoadingHandlers(+ renderOpts.ComponentMod,+ renderOpts.cacheComponents+ )+ } const prepared = await prepareAppPageRender( req, res,@@ -3321,6 +3376,12 @@ async function prerenderToHTMLOrFlightImpl( fallbackRouteParams: OpaqueFallbackRouteParams | null, routeMatch: RouteMatch ) {+ if (renderOpts.ComponentMod.__next_app__) {+ installGlobalModuleLoadingHandlers(+ renderOpts.ComponentMod,+ renderOpts.cacheComponents+ )+ } const isRoutePPREnabled = renderOpts.experimental.isRoutePPREnabled === true const prepared = await prepareAppPageRender( req,@@ -3607,7 +3668,8 @@ async function renderToStream( postponedState: PostponedState | null, metadata: AppPageRenderResultMetadata, createRequestStore: (() => RequestStore) | undefined,- stagedFallbackParams: OpaqueFallbackRouteParams | null+ stagedFallbackParams: OpaqueFallbackRouteParams | null,+ tracker: ClientComponentLoadTracker | undefined ): Promise<AnyStream> { /* eslint-disable @next/internal/no-ambiguous-jsx -- React Client */ // MARK: renderToStream setup@@ -4184,6 +4246,7 @@ async function renderToStream( // End the span since there's no async rendering in this path if (renderSpan.isRecording()) renderSpan.end()+ tracker?.finish() return chainStreams( inlinedDataStream, createDocumentClosingStream()@@ -4219,7 +4282,11 @@ async function renderToStream( resumeToFizzStream, resumeAppElement, postponed,- { onError: htmlRendererErrorHandler, nonce }+ {+ onError: htmlRendererErrorHandler,+ onAllReady: tracker ? () => tracker.finish() : undefined,+ nonce,+ } ) // End the render span only after React completed rendering (including anything inside Suspense boundaries)@@ -4266,6 +4333,7 @@ async function renderToStream( const fizzOptions = { onError: htmlRendererErrorHandler,+ onAllReady: tracker ? () => tracker.finish() : undefined, nonce, onHeaders: (headers: { [header: string]: string }) => { for (const key in headers) {@@ -4325,6 +4393,7 @@ async function renderToStream( // End the span since there's no async rendering in this path if (renderSpan.isRecording()) renderSpan.end()+ tracker?.finish() return chainStreams( inlinedDataStream, createDocumentClosingStream()@@ -4367,6 +4436,7 @@ async function renderToStream( allReady.finally(() => { if (renderSpan.isRecording()) renderSpan.end() })+ finishClientComponentLoadTrackingOnReady(tracker, allReady) return await continueDynamicHTMLResumeWeb(htmlStream, { delayDataUntilFirstHtmlChunk:@@ -4429,6 +4499,7 @@ async function renderToStream( allReady.finally(() => { if (renderSpan.isRecording()) renderSpan.end() })+ finishClientComponentLoadTrackingOnReady(tracker, allReady) return await continueFizzStream(htmlStream, { inlinedDataStream: createWebInlinedDataStream(@@ -4583,6 +4654,7 @@ async function renderToStream( bootstrapScriptContent: errorBootstrapScriptContent, bootstrapScripts: [errorBootstrapScript], formState,+ onAllReady: tracker ? () => tracker.finish() : undefined, }, { waitForAllReady } )@@ -4685,6 +4757,7 @@ async function renderToStream( errorAllReady.finally(() => { if (renderSpan.isRecording()) renderSpan.end() })+ finishClientComponentLoadTrackingOnReady(tracker, errorAllReady) return await continueFizzStream(errorHtmlStream, { inlinedDataStream: createWebInlinedDataStream(@@ -6807,6 +6880,7 @@ function buildDevValidationWorkStore( refreshTagsByCacheKind: new Map(), runInCleanSnapshot: createSnapshot(), shouldTrackFetchMetrics: false,+ clientComponentLoadTracker: undefined, reactServerErrorsByDigest: new Map(), afterContext: noopAfterContext, // Dev validation only ever runs under Cache Components.@@ -6854,7 +6928,7 @@ export async function runValidationInDevFromSnapshot( // so `react-server-dom-*` can resolve client references during the validation // prerenders, exactly as the main render does after loading its module. if (componentMod.__next_app__) {- installGlobalModuleLoadingHandlers(componentMod, true, false)+ installGlobalModuleLoadingHandlers(componentMod, true) } // `requestFallbackRouteParams` reproduces `ctx.getDynamicParamFromSegment`@@ -8557,6 +8631,7 @@ async function validateInstantConfigInBuildWithSample( refreshTagsByCacheKind: new Map(), runInCleanSnapshot: outerWorkStore.runInCleanSnapshot, shouldTrackFetchMetrics: false,+ clientComponentLoadTracker: undefined, reactServerErrorsByDigest: new Map(), } packages/next/src/server/app-render/work-async-storage.external.ts2 + / 0 −
@@ -13,6 +13,7 @@ import { workAsyncStorageInstance } from './work-async-storage-instance' with { import type { LazyResult } from '../lib/lazy-result' import type { DigestedError } from './create-error-handler' import type { ActionRevalidationKind } from '../../shared/lib/action-revalidation-kind'+import type { ClientComponentLoadTracker } from '../client-component-renderer-logger' export interface WorkStore { /**@@ -101,6 +102,7 @@ export interface WorkStore { fetchMetrics?: FetchMetrics shouldTrackFetchMetrics: boolean+ clientComponentLoadTracker: ClientComponentLoadTracker | undefined /** * Tracks pending `"use cache"` invocations within the current request scope,packages/next/src/server/async-storage/work-store.ts1 + / 0 −
@@ -147,6 +147,7 @@ function createWorkStoreImpl( refreshTagsByCacheKind: createRefreshTagsByCacheKind(), runInCleanSnapshot: createSnapshot(), shouldTrackFetchMetrics,+ clientComponentLoadTracker: undefined, reactServerErrorsByDigest: new Map(), } packages/next/src/server/client-component-renderer-logger.test.ts266 + / 126 −
@@ -1,8 +1,14 @@+import { AsyncLocalStorage } from 'async_hooks' import type { AppPageModule } from './route-modules/app-page/module'-import {- getClientComponentLoaderMetrics,- wrapClientComponentLoader,-} from './client-component-renderer-logger'+import type { WorkStore } from './app-render/work-async-storage.external'++type LoggerMod = typeof import('./client-component-renderer-logger')+type WASMod = typeof import('./app-render/work-async-storage.external')++let ClientComponentLoadTracker: LoggerMod['ClientComponentLoadTracker']+let getClientComponentLoaderMetrics: LoggerMod['getClientComponentLoaderMetrics']+let wrapClientComponentLoader: LoggerMod['wrapClientComponentLoader']+let workAsyncStorage: WASMod['workAsyncStorage'] function createComponentModule( require: (@@ -17,121 +23,213 @@ function createComponentModule( } as unknown as AppPageModule } +function createTrackedWorkStore(+ page: string = '/test/page',+ route: string = '/test'+): WorkStore {+ return {+ page,+ route,+ clientComponentLoadTracker: new ClientComponentLoadTracker(),+ } as WorkStore+}++function runWithTrackedWorkStore<T>(fn: () => T): T {+ return workAsyncStorage.run(createTrackedWorkStore(), fn)+}+ describe('client component renderer logger', () => {+ beforeAll(async () => {+ // AsyncLocalStorage must be available before workAsyncStorage is imported.+ // @ts-expect-error+ globalThis.AsyncLocalStorage = AsyncLocalStorage++ const logger = await import('./client-component-renderer-logger')+ ClientComponentLoadTracker = logger.ClientComponentLoadTracker+ getClientComponentLoaderMetrics = logger.getClientComponentLoaderMetrics+ wrapClientComponentLoader = logger.wrapClientComponentLoader+ const workStorage = await import('./app-render/work-async-storage.external')+ workAsyncStorage = workStorage.workAsyncStorage+ })+ afterEach(() => { getClientComponentLoaderMetrics({ reset: true }) jest.restoreAllMocks() }) - it('tracks elapsed boundaries separately from sequential load time', () => {- jest- .spyOn(performance, 'now')- .mockReturnValueOnce(100)- .mockReturnValueOnce(110)- .mockReturnValueOnce(150)- .mockReturnValueOnce(160)+ it('tracks elapsed boundaries separately from sequential load time', () =>+ runWithTrackedWorkStore(() => {+ jest+ .spyOn(performance, 'now')+ .mockReturnValueOnce(100)+ .mockReturnValueOnce(110)+ .mockReturnValueOnce(150)+ .mockReturnValueOnce(160) - const loader = wrapClientComponentLoader(- createComponentModule(- () => undefined,- async () => undefined- ),- true- )+ const loader = wrapClientComponentLoader(+ createComponentModule(+ () => undefined,+ async () => undefined+ )+ ) - loader.require('first')- loader.require('second')+ loader.require('first')+ loader.require('second') - expect(getClientComponentLoaderMetrics()).toEqual({- clientComponentLoadStart: 100,- clientComponentLoadEnd: 160,- clientComponentLoadTimes: 20,- clientComponentLoadCount: 2,- })- })+ expect(getClientComponentLoaderMetrics()).toEqual({+ clientComponentLoadStart: 100,+ clientComponentLoadEnd: 160,+ clientComponentLoadTimes: 20,+ clientComponentLoadCount: 2,+ })+ })) - it('preserves accumulated load time for nested requires', () => {- jest- .spyOn(performance, 'now')- .mockReturnValueOnce(100)- .mockReturnValueOnce(110)- .mockReturnValueOnce(120)- .mockReturnValueOnce(130)+ it('preserves accumulated load time for nested requires', () =>+ runWithTrackedWorkStore(() => {+ jest+ .spyOn(performance, 'now')+ .mockReturnValueOnce(100)+ .mockReturnValueOnce(110)+ .mockReturnValueOnce(120)+ .mockReturnValueOnce(130) - let loader: AppPageModule['__next_app__']- loader = wrapClientComponentLoader(- createComponentModule(- (id) => {- if (id === 'outer') {- loader.require('inner')- }- },- async () => undefined- ),- true- )+ let loader: AppPageModule['__next_app__']+ loader = wrapClientComponentLoader(+ createComponentModule(+ (id) => {+ if (id === 'outer') {+ loader.require('inner')+ }+ },+ async () => undefined+ )+ ) - loader.require('outer')+ loader.require('outer') - expect(getClientComponentLoaderMetrics()).toEqual({- clientComponentLoadStart: 100,- clientComponentLoadEnd: 130,- clientComponentLoadTimes: 40,- clientComponentLoadCount: 2,- })- })+ expect(getClientComponentLoaderMetrics()).toEqual({+ clientComponentLoadStart: 100,+ clientComponentLoadEnd: 130,+ clientComponentLoadTimes: 40,+ clientComponentLoadCount: 2,+ })+ })) - it('tracks the last settlement across overlapping chunk loads', async () => {- jest- .spyOn(performance, 'now')- .mockReturnValueOnce(100)- .mockReturnValueOnce(110)- .mockReturnValueOnce(130)- .mockReturnValueOnce(170)-- let resolveFirst!: () => void- let resolveSecond!: () => void- const first = new Promise<void>((resolve) => {- resolveFirst = resolve- })- const second = new Promise<void>((resolve) => {- resolveSecond = resolve- })- const loader = wrapClientComponentLoader(- createComponentModule(- () => undefined,- (id) => (id === 'first' ? first : second)- ),- true- )+ it('tracks the last settlement across overlapping chunk loads', () =>+ runWithTrackedWorkStore(async () => {+ jest+ .spyOn(performance, 'now')+ .mockReturnValueOnce(100)+ .mockReturnValueOnce(110)+ .mockReturnValueOnce(130)+ .mockReturnValueOnce(170) - expect(loader.loadChunk('first')).toBe(first)- expect(loader.loadChunk('second')).toBe(second)+ let resolveFirst!: () => void+ let resolveSecond!: () => void+ const first = new Promise<void>((resolve) => {+ resolveFirst = resolve+ })+ const second = new Promise<void>((resolve) => {+ resolveSecond = resolve+ })+ const loader = wrapClientComponentLoader(+ createComponentModule(+ () => undefined,+ (id) => (id === 'first' ? first : second)+ )+ ) - resolveSecond()- await second- expect(getClientComponentLoaderMetrics()).toEqual({- clientComponentLoadStart: 100,- clientComponentLoadEnd: 130,- clientComponentLoadTimes: 20,- clientComponentLoadCount: 0,- })+ expect(loader.loadChunk('first')).toBe(first)+ expect(loader.loadChunk('second')).toBe(second) - resolveFirst()- await first- expect(getClientComponentLoaderMetrics()).toEqual({- clientComponentLoadStart: 100,- clientComponentLoadEnd: 170,- clientComponentLoadTimes: 90,- clientComponentLoadCount: 0,- })- })+ resolveSecond()+ await second+ expect(getClientComponentLoaderMetrics()).toEqual({+ clientComponentLoadStart: 100,+ clientComponentLoadEnd: 130,+ clientComponentLoadTimes: 20,+ clientComponentLoadCount: 0,+ }) - it('leaves the end boundary unset while a chunk load is pending', async () => {+ resolveFirst()+ await first+ expect(getClientComponentLoaderMetrics()).toEqual({+ clientComponentLoadStart: 100,+ clientComponentLoadEnd: 170,+ clientComponentLoadTimes: 90,+ clientComponentLoadCount: 0,+ })+ }))++ it('leaves the end boundary unset while a chunk load is pending', () =>+ runWithTrackedWorkStore(async () => {+ jest+ .spyOn(performance, 'now')+ .mockReturnValueOnce(100)+ .mockReturnValueOnce(150)++ let resolveChunk!: () => void+ const chunk = new Promise<void>((resolve) => {+ resolveChunk = resolve+ })+ const loader = wrapClientComponentLoader(+ createComponentModule(+ () => undefined,+ () => chunk+ )+ )++ expect(loader.loadChunk('pending')).toBe(chunk)+ expect(getClientComponentLoaderMetrics()).toEqual({+ clientComponentLoadStart: 100,+ clientComponentLoadEnd: 0,+ clientComponentLoadTimes: 0,+ clientComponentLoadCount: 0,+ })++ resolveChunk()+ await chunk+ expect(getClientComponentLoaderMetrics()).toEqual({+ clientComponentLoadStart: 100,+ clientComponentLoadEnd: 150,+ clientComponentLoadTimes: 50,+ clientComponentLoadCount: 0,+ })+ }))++ it('tracks rejected chunk loads without changing the returned promise', () =>+ runWithTrackedWorkStore(async () => {+ jest+ .spyOn(performance, 'now')+ .mockReturnValueOnce(100)+ .mockReturnValueOnce(150)++ const error = new Error('chunk failed')+ const chunk = Promise.reject(error)+ const loader = wrapClientComponentLoader(+ createComponentModule(+ () => undefined,+ () => chunk+ )+ )++ expect(loader.loadChunk('rejected')).toBe(chunk)+ await expect(chunk).rejects.toBe(error)+ expect(getClientComponentLoaderMetrics()).toEqual({+ clientComponentLoadStart: 100,+ clientComponentLoadEnd: 150,+ clientComponentLoadTimes: 50,+ clientComponentLoadCount: 0,+ })+ }))++ it('attributes a pending chunk to its render while another render runs', async () => { jest .spyOn(performance, 'now') .mockReturnValueOnce(100)- .mockReturnValueOnce(150)+ .mockReturnValueOnce(200)+ .mockReturnValueOnce(220)+ .mockReturnValueOnce(300) let resolveChunk!: () => void const chunk = new Promise<void>((resolve) => {@@ -141,50 +239,92 @@ describe('client component renderer logger', () => { createComponentModule( () => undefined, () => chunk- ),- true+ ) )+ const firstWorkStore = createTrackedWorkStore('/first/page', '/first')+ const secondWorkStore = createTrackedWorkStore('/second/page', '/second')+ expect(+ workAsyncStorage.run(firstWorkStore, () => loader.loadChunk('first'))+ ).toBe(chunk) - expect(loader.loadChunk('pending')).toBe(chunk)- expect(getClientComponentLoaderMetrics()).toEqual({- clientComponentLoadStart: 100,- clientComponentLoadEnd: 0,- clientComponentLoadTimes: 0,- clientComponentLoadCount: 0,- })-+ workAsyncStorage.run(secondWorkStore, () => loader.require('second')) resolveChunk() await chunk- expect(getClientComponentLoaderMetrics()).toEqual({++ expect(+ workAsyncStorage.run(firstWorkStore, () =>+ getClientComponentLoaderMetrics()+ )+ ).toEqual({ clientComponentLoadStart: 100,- clientComponentLoadEnd: 150,- clientComponentLoadTimes: 50,+ clientComponentLoadEnd: 300,+ clientComponentLoadTimes: 200, clientComponentLoadCount: 0, })+ expect(+ workAsyncStorage.run(secondWorkStore, () =>+ getClientComponentLoaderMetrics()+ )+ ).toEqual({+ clientComponentLoadStart: 200,+ clientComponentLoadEnd: 220,+ clientComponentLoadTimes: 20,+ clientComponentLoadCount: 1,+ }) }) - it('tracks rejected chunk loads without changing the returned promise', async () => {- jest- .spyOn(performance, 'now')- .mockReturnValueOnce(100)- .mockReturnValueOnce(150)+ it('finishes once and ignores loads started afterward', async () => {+ const report = jest.fn()+ const tracker = new ClientComponentLoadTracker(report)+ tracker.beginRequire(100)+ tracker.finishRequire(100, 120)+ tracker.finish()+ tracker.finish() - const error = new Error('chunk failed')- const chunk = Promise.reject(error)+ const workStore = createTrackedWorkStore()+ workStore.clientComponentLoadTracker = tracker const loader = wrapClientComponentLoader( createComponentModule( () => undefined,- () => chunk- ),- true+ async () => undefined+ ) )+ workAsyncStorage.run(workStore, () => loader.require('after-finish'))+ await Promise.resolve() - expect(loader.loadChunk('rejected')).toBe(chunk)- await expect(chunk).rejects.toBe(error)- expect(getClientComponentLoaderMetrics()).toEqual({+ expect(report).toHaveBeenCalledTimes(1)+ expect(report).toHaveBeenCalledWith({ clientComponentLoadStart: 100,- clientComponentLoadEnd: 150,- clientComponentLoadTimes: 50,+ clientComponentLoadEnd: 120,+ clientComponentLoadTimes: 20,+ clientComponentLoadCount: 1,+ })+ })++ it('reports once after every pending chunk settles', async () => {+ let resolveReport!: () => void+ const reported = new Promise<void>((resolve) => {+ resolveReport = resolve+ })+ const report = jest.fn(() => resolveReport())+ const tracker = new ClientComponentLoadTracker(report)+ tracker.beginChunk(100)+ tracker.beginChunk(110)+ tracker.finish()+ await Promise.resolve()+ expect(report).not.toHaveBeenCalled()++ tracker.finishChunk(110, 130)+ await Promise.resolve()+ expect(report).not.toHaveBeenCalled()++ tracker.finishChunk(100, 170)+ await reported+ expect(report).toHaveBeenCalledTimes(1)+ expect(report).toHaveBeenCalledWith({+ clientComponentLoadStart: 100,+ clientComponentLoadEnd: 170,+ clientComponentLoadTimes: 90, clientComponentLoadCount: 0, }) })packages/next/src/server/client-component-renderer-logger.ts133 + / 44 −
@@ -1,53 +1,149 @@ import type { AppPageModule } from './route-modules/app-page/module'+import { workAsyncStorage } from './app-render/work-async-storage.external' -// Combined load times for loading client components-let clientComponentLoadStart = 0-let clientComponentLoadEnd = 0-let clientComponentLoadTimes = 0-let clientComponentLoadCount = 0+export type ClientComponentLoaderMetrics = {+ clientComponentLoadStart: number+ clientComponentLoadEnd: number+ clientComponentLoadTimes: number+ clientComponentLoadCount: number+}++/** Metrics owned by one render, including chunks that settle after rendering. */+export class ClientComponentLoadTracker {+ private clientComponentLoadStart = 0+ private clientComponentLoadEnd = 0+ private clientComponentLoadTimes = 0+ private clientComponentLoadCount = 0+ private hasLoads = false+ private pending = 0+ private sealed = false+ private resolveCompletion:+ | ((metrics: ClientComponentLoaderMetrics | undefined) => void)+ | undefined = undefined++ constructor(+ private readonly report: (+ metrics: ClientComponentLoaderMetrics | undefined+ ) => void = () => {}+ ) {}++ isSealed(): boolean {+ return this.sealed+ }++ beginRequire(startTime: number): void {+ this.recordStart(startTime)+ this.clientComponentLoadCount+++ this.pending+++ }++ finishRequire(startTime: number, endTime: number): void {+ this.recordSettlement(startTime, endTime)+ }++ beginChunk(startTime: number): void {+ this.recordStart(startTime)+ this.pending+++ }++ finishChunk(startTime: number, endTime: number): void {+ this.recordSettlement(startTime, endTime)+ }++ snapshot(): ClientComponentLoaderMetrics | undefined {+ if (!this.hasLoads) {+ return undefined+ }++ return {+ clientComponentLoadStart: this.clientComponentLoadStart,+ clientComponentLoadEnd: this.clientComponentLoadEnd,+ clientComponentLoadTimes: this.clientComponentLoadTimes,+ clientComponentLoadCount: this.clientComponentLoadCount,+ }+ }++ /** Stop accepting new loads and report after any in-flight loads settle. */+ finish(): void {+ if (this.sealed) return+ this.sealed = true+ let completion: Promise<ClientComponentLoaderMetrics | undefined>+ if (this.pending === 0) {+ completion = Promise.resolve(this.snapshot())+ } else {+ completion = new Promise((resolve) => {+ this.resolveCompletion = resolve+ })+ }++ // Telemetry is best-effort and must not keep the response open or mask a+ // render error, including when reporting fails.+ void completion.then(this.report).catch((error) => {+ console.error('Failed to report client component loading metrics:', error)+ })+ }++ private recordStart(startTime: number): void {+ if (!this.hasLoads) {+ this.hasLoads = true+ this.clientComponentLoadStart = startTime+ }+ }++ private recordSettlement(startTime: number, endTime: number): void {+ this.clientComponentLoadEnd = endTime+ this.clientComponentLoadTimes += endTime - startTime+ this.pending--++ if (this.sealed && this.pending === 0 && this.resolveCompletion) {+ const resolve = this.resolveCompletion+ this.resolveCompletion = undefined+ resolve(this.snapshot())+ }+ }+} export function wrapClientComponentLoader(- ComponentMod: AppPageModule,- isTracingEnabled: boolean+ ComponentMod: AppPageModule ): AppPageModule['__next_app__'] {- if (- !('performance' in globalThis) ||- (!process.env.NEXT_OTEL_PERFORMANCE_PREFIX && !isTracingEnabled)- ) {+ if (!('performance' in globalThis)) { return ComponentMod.__next_app__ } return { require: (...args) => {- const startTime = performance.now()-- if (clientComponentLoadStart === 0) {- clientComponentLoadStart = startTime+ const tracker = workAsyncStorage.getStore()?.clientComponentLoadTracker+ if (tracker === undefined || tracker.isSealed()) {+ return ComponentMod.__next_app__.require(...args) } + const startTime = performance.now()+ tracker.beginRequire(startTime) try {- clientComponentLoadCount += 1 return ComponentMod.__next_app__.require(...args) } finally {- const endTime = performance.now()- clientComponentLoadEnd = endTime- clientComponentLoadTimes += endTime - startTime+ tracker.finishRequire(startTime, performance.now()) } }, loadChunk: (...args) => {- const startTime = performance.now()+ const tracker = workAsyncStorage.getStore()?.clientComponentLoadTracker+ if (tracker === undefined || tracker.isSealed()) {+ return ComponentMod.__next_app__.loadChunk(...args)+ } - if (clientComponentLoadStart === 0) {- clientComponentLoadStart = startTime+ const startTime = performance.now()+ tracker.beginChunk(startTime)+ let result: ReturnType<AppPageModule['__next_app__']['loadChunk']>+ try {+ result = ComponentMod.__next_app__.loadChunk(...args)+ } catch (error) {+ tracker.finishChunk(startTime, performance.now())+ throw error } - const result = ComponentMod.__next_app__.loadChunk(...args)- // Avoid wrapping `loadChunk`'s result in an extra promise in case something like React depends on its identity.- // We only need to know when it's settled.+ // React can depend on the original promise identity. const onSettled = () => {- const endTime = performance.now()- clientComponentLoadEnd = endTime- clientComponentLoadTimes += endTime - startTime+ tracker.finishChunk(startTime, performance.now()) } result.then(onSettled, onSettled) return result@@ -57,22 +153,15 @@ export function wrapClientComponentLoader( export function getClientComponentLoaderMetrics( options: { reset?: boolean } = {}-) {- const metrics =- clientComponentLoadStart === 0- ? undefined- : {- clientComponentLoadStart,- clientComponentLoadEnd,- clientComponentLoadTimes,- clientComponentLoadCount,- }-- if (options.reset) {- clientComponentLoadStart = 0- clientComponentLoadEnd = 0- clientComponentLoadTimes = 0- clientComponentLoadCount = 0+): ClientComponentLoaderMetrics | undefined {+ const workStore = workAsyncStorage.getStore()+ const tracker = workStore?.clientComponentLoadTracker+ const metrics = tracker?.snapshot()++ if (options.reset && workStore) {+ // Pending settlements still hold their original tracker. Detaching it only+ // affects subsequent reads and loads in this render.+ workStore.clientComponentLoadTracker = undefined } return metricspackages/next/src/server/dev/use-cache-probe-worker.ts1 + / 0 −
@@ -217,6 +217,7 @@ function buildProbeWorkStore(msg: ProbeMessage): WorkStore { refreshTagsByCacheKind: new Map(), runInCleanSnapshot: createSnapshot(), shouldTrackFetchMetrics: false,+ clientComponentLoadTracker: undefined, reactServerErrorsByDigest: new Map(), afterContext, cacheComponentsEnabled: true,packages/next/src/server/pipe-readable.test.ts104 + / 1 −
@@ -7,11 +7,12 @@ import type { AddressInfo } from 'node:net' import { EventEmitter } from 'node:events' import http from 'node:http' import zlib from 'node:zlib'-import { Readable } from 'node:stream'+import { PassThrough, Readable } from 'node:stream' import { promisify } from 'node:util' import setupCompression from 'next/dist/compiled/compression' import { pipeNodeReadableToNodeResponse } from './pipe-readable'+import { ClientComponentLoadTracker } from './client-component-renderer-logger' const gunzip = promisify(zlib.gunzip) @@ -173,3 +174,105 @@ describe('pipeNodeReadableToNodeResponse', () => { expect(decompressed.every((byte) => byte === FILL)).toBe(true) }) })++describe('client component loading measurement at first write', () => {+ let server: http.Server | undefined+ let measure: jest.SpyInstance+ let pipe: typeof import('./pipe-readable')+ const previousPrefix = process.env.NEXT_OTEL_PERFORMANCE_PREFIX++ beforeAll(() => {+ process.env.NEXT_OTEL_PERFORMANCE_PREFIX = 'test'+ jest.isolateModules(() => {+ pipe = require('./pipe-readable') as typeof import('./pipe-readable')+ })+ })++ afterAll(() => {+ if (previousPrefix === undefined) {+ delete process.env.NEXT_OTEL_PERFORMANCE_PREFIX+ } else {+ process.env.NEXT_OTEL_PERFORMANCE_PREFIX = previousPrefix+ }+ })++ beforeEach(() => {+ measure = jest.spyOn(performance, 'measure').mockImplementation(() => {+ return {} as PerformanceMeasure+ })+ })++ afterEach(async () => {+ measure.mockRestore()+ if (server) {+ server.closeAllConnections()+ await new Promise<void>((resolve) => server!.close(() => resolve()))+ server = undefined+ }+ })++ it.each(['web', 'node'] as const)(+ 'measures the explicit %s tracker when the first chunk is written',+ async (streamKind) => {+ const tracker = new ClientComponentLoadTracker()+ tracker.beginRequire(100)+ tracker.finishRequire(100, 115)+ tracker.beginRequire(150)+ tracker.finishRequire(150, 160)+ tracker.beginChunk(200)+ const firstWrite = new Promise<void>((resolve) => {+ measure.mockImplementation(() => {+ resolve()+ return {} as PerformanceMeasure+ })+ })++ function loadAfterFirstWrite() {+ tracker.beginRequire(300)+ tracker.finishRequire(300, 330)+ }++ server = http.createServer((_req, res) => {+ if (streamKind === 'web') {+ const readable = new ReadableStream<Uint8Array>({+ start(controller) {+ setImmediate(() => {+ tracker.finishChunk(200, 250)+ controller.enqueue(new TextEncoder().encode('hello'))+ void firstWrite.then(() => {+ loadAfterFirstWrite()+ controller.enqueue(new TextEncoder().encode(' world'))+ controller.close()+ })+ })+ },+ })+ void pipe+ .pipeToNodeResponse(readable, res, undefined, tracker)+ .catch((error) => res.destroy(error))+ } else {+ const readable = new PassThrough()+ void pipe+ .pipeNodeReadableToNodeResponse(readable, res, undefined, tracker)+ .catch((error) => res.destroy(error))+ setImmediate(() => {+ tracker.finishChunk(200, 250)+ readable.write('hello')+ void firstWrite.then(() => {+ loadAfterFirstWrite()+ readable.end(' world')+ })+ })+ }+ })++ const url = await listen(server)+ expect(await (await fetch(url)).text()).toBe('hello world')+ expect(measure).toHaveBeenCalledTimes(1)+ expect(measure).toHaveBeenCalledWith(+ 'test:next-client-component-loading',+ { start: 100, end: 175 }+ )+ }+ )+})packages/next/src/server/pipe-readable.ts14 + / 7 −
@@ -8,7 +8,7 @@ import { import { createPromiseWithResolvers } from '../shared/lib/promise-with-resolvers' import { getTracer } from './lib/trace/tracer' import { NextNodeServerSpan } from './lib/trace/constants'-import { getClientComponentLoaderMetrics } from './client-component-renderer-logger'+import type { ClientComponentLoadTracker } from './client-component-renderer-logger' export function isAbortError(e: any): e is Error & { name: 'AbortError' } { return e?.name === 'AbortError' || e?.name === ResponseAbortedName@@ -19,7 +19,8 @@ const HAS_CLIENT_COMPONENT_METRICS_ENABLED = function createWriterFromResponse( res: ServerResponse,- waitUntilForEnd?: Promise<unknown>+ waitUntilForEnd?: Promise<unknown>,+ clientComponentLoadTracker?: ClientComponentLoadTracker ): WritableStream<Uint8Array> { let started = false @@ -55,7 +56,7 @@ function createWriterFromResponse( started = true if (HAS_CLIENT_COMPONENT_METRICS_ENABLED) {- const metrics = getClientComponentLoaderMetrics()+ const metrics = clientComponentLoadTracker?.snapshot() if (metrics) { performance.measure( `${process.env.NEXT_OTEL_PERFORMANCE_PREFIX}:next-client-component-loading`,@@ -124,7 +125,8 @@ function createWriterFromResponse( export async function pipeToNodeResponse( readable: ReadableStream<Uint8Array>, res: ServerResponse,- waitUntilForEnd?: Promise<unknown>+ waitUntilForEnd?: Promise<unknown>,+ clientComponentLoadTracker?: ClientComponentLoadTracker ) { try { // If the response has already errored, then just return now.@@ -135,7 +137,11 @@ export async function pipeToNodeResponse( // client disconnects. const controller = createAbortController(res) - const writer = createWriterFromResponse(res, waitUntilForEnd)+ const writer = createWriterFromResponse(+ res,+ waitUntilForEnd,+ clientComponentLoadTracker+ ) await readable.pipeTo(writer, { signal: controller.signal }) } catch (err: any) {@@ -149,7 +155,8 @@ export async function pipeToNodeResponse( export async function pipeNodeReadableToNodeResponse( readable: Readable, res: ServerResponse,- waitUntilForEnd?: Promise<unknown>+ waitUntilForEnd?: Promise<unknown>,+ clientComponentLoadTracker?: ClientComponentLoadTracker ) { try { const { errored, destroyed } = res@@ -201,7 +208,7 @@ export async function pipeNodeReadableToNodeResponse( 'performance' in globalThis && process.env.NEXT_OTEL_PERFORMANCE_PREFIX ) {- const metrics = getClientComponentLoaderMetrics()+ const metrics = clientComponentLoadTracker?.snapshot() if (metrics) { performance.measure( `${process.env.NEXT_OTEL_PERFORMANCE_PREFIX}:next-client-component-loading`,packages/next/src/server/render-result.ts15 + / 2 −
@@ -3,6 +3,7 @@ import type { Readable } from 'stream' import type { CacheControl } from './lib/cache-control' import type { FetchMetrics } from './base-http' import type { PrefetchHints } from '../shared/lib/app-router-types'+import type { ClientComponentLoadTracker } from './client-component-renderer-logger' import { chainStreams,@@ -31,6 +32,8 @@ type ContentTypeOption = | typeof TEXT_PLAIN_CONTENT_TYPE_HEADER // For simplified errors export type AppPageRenderResultMetadata = {+ /** Request-local metrics for the first response write. Never cache this. */+ clientComponentLoadTracker?: ClientComponentLoadTracker flightData?: Buffer cacheControl?: CacheControl staticBailoutInfo?: {@@ -431,9 +434,19 @@ export default class RenderResult< !Array.isArray(this.response) && isNodeReadable(this.response) ) {- await pipeNodeReadableToNodeResponse(this.response, res, this.waitUntil)+ await pipeNodeReadableToNodeResponse(+ this.response,+ res,+ this.waitUntil,+ this.metadata.clientComponentLoadTracker+ ) return }- await pipeToNodeResponse(this.readable, res, this.waitUntil)+ await pipeToNodeResponse(+ this.readable,+ res,+ this.waitUntil,+ this.metadata.clientComponentLoadTracker+ ) } }test/e2e/opentelemetry/instrumentation/app/api/app/[param]/client-component-flush/route.tsadded18 + / 0 −
@@ -0,0 +1,18 @@+const forceFlushKey = Symbol.for('opentelemetry.test/forceFlush')++export const runtime = 'nodejs'++export async function POST() {+ const flush = (+ globalThis as typeof globalThis &+ Record<symbol, (() => Promise<void>) | undefined>+ )[forceFlushKey]+ if (!flush) {+ return new Response('OpenTelemetry test flush hook is unavailable', {+ status: 503,+ })+ }++ await flush()+ return new Response(null, { status: 204 })+}test/e2e/opentelemetry/instrumentation/app/app/[param]/client-component-action/action-only-client.tsxadded5 + / 0 −
@@ -0,0 +1,5 @@+'use client'++export default function ActionOnlyClient() {+ return <span>Action-only client component</span>+}test/e2e/opentelemetry/instrumentation/app/app/[param]/client-component-action/page.tsxadded39 + / 0 −
@@ -0,0 +1,39 @@+import { trace } from '@opentelemetry/api'+import { cookies } from 'next/headers'+import EarlyClient from '../client-component-loading/early-client'+import LateClient from '../client-component-loading/late-client'+import ActionOnlyClient from './action-only-client'++export default async function Page() {+ const marker =+ (await cookies()).get('client-component-action-marker')?.value ?? 'none'+ const capturedClient = ActionOnlyClient++ async function setMarker(formData: FormData) {+ 'use server'+ if (!capturedClient) {+ throw new Error('Missing captured client component')+ }+ const value = formData.get('marker')+ if (typeof value !== 'string') {+ throw new Error('Missing action marker')+ }+ ;(await cookies()).set('client-component-action-marker', value)+ trace+ .getTracer('client-component-loading-test')+ .startSpan('test.serverActionCompleted')+ .end()+ }++ return (+ <>+ <EarlyClient />+ <LateClient />+ <p id="action-result">{marker}</p>+ <form action={setMarker}>+ <input type="hidden" name="marker" value="action-completed" />+ <button type="submit">Run action</button>+ </form>+ </>+ )+}test/e2e/opentelemetry/instrumentation/app/app/[param]/client-component-html-boundary/async-client.tsxadded7 + / 0 −
@@ -0,0 +1,7 @@+'use client'++await Promise.resolve()++export default function AsyncClient() {+ return <span id="unused-client">unused client component</span>+}test/e2e/opentelemetry/instrumentation/app/app/[param]/client-component-html-boundary/initially-closed-panel.tsxadded19 + / 0 −
@@ -0,0 +1,19 @@+'use client'++import { useState, type ReactNode } from 'react'++export default function InitiallyClosedPanel({+ children,+}: {+ children: ReactNode+}) {+ const [open, setOpen] = useState(false)+ return (+ <section id="closed-panel">+ <button type="button" onClick={() => setOpen(true)}>+ Open+ </button>+ {open ? children : 'closed'}+ </section>+ )+}test/e2e/opentelemetry/instrumentation/app/app/[param]/client-component-html-boundary/page.tsxadded28 + / 0 −
@@ -0,0 +1,28 @@+import { Suspense } from 'react'+import AsyncClient from './async-client'+import InitiallyClosedPanel from './initially-closed-panel'++async function SlowDetails({ id }: { id: string }) {+ const response = await fetch(+ `http://localhost:${process.env.TEST_CLIENT_COMPONENT_GATE_PORT}/?key=${id}`,+ { cache: 'no-store' }+ )+ if (!response.ok) throw new Error('Details gate failed')+ return <AsyncClient />+}++export default async function Page({+ searchParams,+}: {+ searchParams: Promise<{ id?: string }>+}) {+ const { id } = await searchParams+ if (!id) throw new Error('Missing details gate id')+ return (+ <InitiallyClosedPanel>+ <Suspense fallback={<span id="details-fallback">waiting</span>}>+ <SlowDetails id={id} />+ </Suspense>+ </InitiallyClosedPanel>+ )+}test/e2e/opentelemetry/instrumentation/app/app/[param]/client-component-loading/early-client.tsxadded5 + / 0 −
@@ -0,0 +1,5 @@+'use client'++export default function EarlyClient() {+ return <span id="early-client">early client component</span>+}test/e2e/opentelemetry/instrumentation/app/app/[param]/client-component-loading/extra-late-client.tsxadded5 + / 0 −
@@ -0,0 +1,5 @@+'use client'++export default function ExtraLateClient() {+ return <span id="extra-late-client">extra late client component</span>+}test/e2e/opentelemetry/instrumentation/app/app/[param]/client-component-loading/late-client.tsxadded5 + / 0 −
@@ -0,0 +1,5 @@+'use client'++export default function LateClient() {+ return <span id="late-client">late client component</span>+}test/e2e/opentelemetry/instrumentation/app/app/[param]/client-component-loading/page.tsxadded45 + / 0 −
@@ -0,0 +1,45 @@+import { Suspense } from 'react'+import EarlyClient from './early-client'+import ExtraLateClient from './extra-late-client'+import LateClient from './late-client'++async function GatedContent({ id, extra }: { id: string; extra: boolean }) {+ const response = await fetch(+ `http://localhost:${process.env.TEST_CLIENT_COMPONENT_GATE_PORT}/?key=${id}`,+ { cache: 'no-store' }+ )+ if (!response.ok) {+ throw new Error(`Gate request failed: ${response.status}`)+ }++ return (+ <>+ <LateClient />+ {extra && <ExtraLateClient />}+ </>+ )+}++export default async function Page({+ searchParams,+}: {+ searchParams: Promise<{ [key: string]: string | string[] | undefined }>+}) {+ const { id, variant } = await searchParams+ if (typeof id !== 'string') {+ throw new Error('Missing client component gate id')+ }+ if (variant !== undefined && variant !== 'extra') {+ throw new Error('Invalid client component loading variant')+ }+ const extra = variant === 'extra'++ return (+ <>+ <EarlyClient />+ <Suspense fallback={<span id="waiting">waiting</span>}>+ <GatedContent id={id} extra={extra} />+ </Suspense>+ </>+ )+}test/e2e/opentelemetry/instrumentation/instrumentation-test.ts26 + / 2 −
@@ -28,6 +28,7 @@ import { import { SavedSpan } from './constants' const customKey = Symbol.for('opentelemetry.test/custom')+const forceFlushKey = Symbol.for('opentelemetry.test/forceFlush') const serializeSpan = (span: ReadableSpan): SavedSpan => ({ runtime: process.env.NEXT_RUNTIME,@@ -46,12 +47,26 @@ const serializeSpan = (span: ReadableSpan): SavedSpan => ({ }) class TestExporter implements SpanExporter {+ private pendingExports = new Set<Promise<void>>()+ constructor(private port: number) {} - async export(+ export( spans: ReadableSpan[], resultCallback: (result: ExportResult) => void- ) {+ ): void {+ const pending = this.exportSpans(spans, resultCallback)+ this.pendingExports.add(pending)+ void pending.then(+ () => this.pendingExports.delete(pending),+ () => this.pendingExports.delete(pending)+ )+ }++ private async exportSpans(+ spans: ReadableSpan[],+ resultCallback: (result: ExportResult) => void+ ): Promise<void> { try { const response = await fetch(`http://localhost:${this.port}`, { method: 'POST',@@ -82,6 +97,12 @@ class TestExporter implements SpanExporter { shutdown(): Promise<void> { return Promise.resolve() }++ async forceFlush(): Promise<void> {+ // SimpleSpanProcessor does not await ordinary exports in forceFlush, so+ // drain this test exporter's pending HTTP requests explicitly.+ await Promise.all(this.pendingExports)+ } } export const register = () => {@@ -107,6 +128,9 @@ export const register = () => { propagators: [new CustomPropagator(), new W3CTraceContextPropagator()], }), })+ ;(globalThis as typeof globalThis & Record<symbol, () => Promise<void>>)[+ forceFlushKey+ ] = () => provider.forceFlush() } class CustomPropagator implements TextMapPropagator {test/e2e/opentelemetry/instrumentation/opentelemetry.test.ts376 + / 50 −
@@ -1,5 +1,7 @@ import { FileRef, isNextDev, isNextStart, nextTestSetup } from 'e2e-utils' import { retry } from 'next-test-utils'+import { createTestDataServer } from 'test-data-service/writer'+import { createTestLog } from 'test-log' import { NEXT_RSC_UNION_QUERY } from 'next/dist/client/components/app-router-headers' import path from 'path' @@ -15,6 +17,7 @@ const COLLECTOR_PORT = 9001 const ROUTE_PREPARATION_COLLECTOR_PORT = 9002 const INSTRUMENTATION_STARTUP_COLLECTOR_PORT = 9003 const APP_ROUTE_MODULE_LOADING_COLLECTOR_PORT = 9004+const CLIENT_COMPONENT_GATE_PORT = 9005 type NextInstance = ReturnType<typeof nextTestSetup>['next'] @@ -54,6 +57,7 @@ function setup({ useDirectEntrypointHandler, useNodeMiddleware }) { ? { env: { TEST_OTEL_COLLECTOR_PORT: String(COLLECTOR_PORT),+ TEST_CLIENT_COMPONENT_GATE_PORT: String(CLIENT_COMPONENT_GATE_PORT), NEXT_TELEMETRY_DISABLED: '1', }, }@@ -147,6 +151,329 @@ describe.each( expect(response.headers.get('connection')).toBe('close') }) + // The custom entrypoint server has an explicit route table and does not+ // include this streamed page.+ if (!useDirectEntrypointHandler) {+ describe('client component loading across streamed renders', () => {+ const pendingGates = new Map<string, () => void>()+ const gateServer = createTestDataServer((id, response) => {+ pendingGates.set(id, () => response.resolve())+ gateArrivals.log(id)+ })+ let gateArrivals = createTestLog()+ let traceNumber = 0++ function newTraceId() {+ return (++traceNumber).toString(16).padStart(32, '0')+ }++ function traceparent(traceId: string) {+ return `00-${traceId}-${'1'.repeat(16)}-01`+ }++ beforeAll(() => gateServer.listen(CLIENT_COMPONENT_GATE_PORT))+ beforeEach(() => {+ gateArrivals = createTestLog()+ })+ afterEach(() => {+ for (const release of pendingGates.values()) release()+ pendingGates.clear()+ })+ afterAll(() => gateServer.close())++ function releaseGate(id: string) {+ const gate = pendingGates.get(id)+ expect(gate).toBeDefined()+ pendingGates.delete(id)+ gate!()+ }++ async function openPage({+ id,+ traceId,+ extra = false,+ }: {+ id: string+ traceId: string+ extra?: boolean+ }) {+ const responsePromise = next.fetch(+ `/app/test/client-component-loading?id=${id}${extra ? '&variant=extra' : ''}`,+ { headers: { traceparent: traceparent(traceId) } }+ )+ await gateArrivals.waitFor([id])+ const response = await responsePromise+ expect(response.status).toBe(200)+ return response+ }++ async function finishPage(response: Response, extra = false) {+ const html = await response.text()+ expect(html).toContain('<span id="early-client">')+ expect(html).toContain('<span id="late-client">')+ if (extra) expect(html).toContain('<span id="extra-late-client">')+ }++ function loadingSpans(traceId: string): SavedSpan[] {+ return getCollector()+ .getSpans()+ .filter(+ (span) =>+ span.traceId === traceId &&+ span.attributes?.['next.span_type'] ===+ 'NextNodeServer.clientComponentLoading'+ )+ }++ async function expectNoLoadingSpanWhileBlocked(traceId: string) {+ // Flush in-flight exports before making a negative assertion.+ const response = await next.fetch(+ '/api/app/test/client-component-flush',+ { method: 'POST' }+ )+ expect(response.status).toBe(204)+ expect(loadingSpans(traceId)).toEqual([])+ }++ async function loadCount(traceId: string): Promise<number> {+ return retry(() => {+ const spans = loadingSpans(traceId)+ expect(spans).toHaveLength(1)+ const requestSpans = getCollector()+ .getSpans()+ .filter(+ (span) =>+ span.traceId === traceId &&+ span.attributes?.['next.span_type'] ===+ 'BaseServer.handleRequest'+ )+ expect(requestSpans).toHaveLength(1)+ expect(spans[0].parentId).toBe(requestSpans[0].id)+ const count = spans[0].attributes?.[+ 'next.clientComponentLoadCount'+ ] as number+ expect(count).toBeGreaterThan(0)+ return count+ })+ }++ async function renderBaseline(extra: boolean): Promise<number> {+ const traceId = newTraceId()+ const id = `baseline-${traceId}`+ const response = await openPage({ id, traceId, extra })+ releaseGate(id)+ await finishPage(response, extra)+ return loadCount(traceId)+ }++ it.each(['a', 'b'] as const)(+ 'keeps overlapping render metrics when %s finishes first',+ async (finishFirst) => {+ // Warm both module sets before measuring the sequential baselines.+ await renderBaseline(false)+ await renderBaseline(true)+ const normalCount = await renderBaseline(false)+ const extraCount = await renderBaseline(true)+ expect(extraCount).toBeGreaterThan(normalCount)++ const traceA = newTraceId()+ const traceB = newTraceId()+ const responseA = await openPage({ id: 'a', traceId: traceA })+ const responseB = await openPage({+ id: 'b',+ traceId: traceB,+ extra: true,+ })+ await expectNoLoadingSpanWhileBlocked(traceA)+ await expectNoLoadingSpanWhileBlocked(traceB)++ const requests = {+ a: {+ id: 'a',+ response: responseA,+ traceId: traceA,+ count: normalCount,+ extra: false,+ },+ b: {+ id: 'b',+ response: responseB,+ traceId: traceB,+ count: extraCount,+ extra: true,+ },+ }+ const first = requests[finishFirst]+ const second = requests[finishFirst === 'a' ? 'b' : 'a']++ releaseGate(first.id)+ await finishPage(first.response, first.extra)+ expect(await loadCount(first.traceId)).toBe(first.count)++ expect(pendingGates.has(second.id)).toBe(true)+ await expectNoLoadingSpanWhileBlocked(second.traceId)+ releaseGate(second.id)+ await finishPage(second.response, second.extra)+ expect(await loadCount(second.traceId)).toBe(second.count)+ }+ )++ const actionPath = '/app/test/client-component-action'++ async function getActionPage(traceId: string) {+ const $ = await next.render$(actionPath, undefined, {+ headers: { traceparent: traceparent(traceId) },+ })+ expect($('#action-result').text()).toBe('none')+ return { $, count: await loadCount(traceId) }+ }++ it('reports HTML loading after a form POST and leaves the next GET unchanged', async () => {+ await getActionPage(newTraceId())+ const { $, count: baseline } = await getActionPage(newTraceId())+ const form = $('form').first()+ expect(form.length).toBe(1)+ const formData = new FormData()+ form.find('input[type="hidden"]').each((_, input) => {+ const name = $(input).attr('name')+ if (name) formData.append(name, $(input).attr('value') ?? '')+ })+ formData.set('marker', 'action-completed')++ const actionTrace = newTraceId()+ const response = await next.fetch(actionPath, {+ method: 'POST',+ headers: {+ traceparent: traceparent(actionTrace),+ origin: new URL(next.url).origin,+ },+ body: formData,+ })+ expect(response.status).toBe(200)+ expect(await response.text()).toContain(+ '<p id="action-result">action-completed</p>'+ )+ await retry(() => {+ expect(+ getCollector()+ .getSpans()+ .filter(+ (span) =>+ span.traceId === actionTrace &&+ span.name === 'test.serverActionCompleted'+ )+ ).toHaveLength(1)+ })+ await loadCount(actionTrace)++ const { count: nextGetCount } = await getActionPage(newTraceId())+ expect(nextGetCount).toBe(baseline)+ })++ it('does not report HTML loading metrics for an enhanced Server Action', async () => {+ const browser = await next.browser(actionPath)+ expect(await browser.elementByCss('#action-result').text()).toBe('none')++ // Flush the initial document's metrics before measuring the action.+ const flush = async () => {+ const response = await next.fetch(+ '/api/app/test/client-component-flush',+ { method: 'POST' }+ )+ expect(response.status).toBe(204)+ }+ await flush()+ getCollector().reset()++ await browser.elementByCss('button[type="submit"]').click()+ await retry(async () => {+ expect(await browser.elementByCss('#action-result').text()).toBe(+ 'action-completed'+ )+ })+ await flush()+ const actionRequest = await retry(() => {+ const requests = getCollector()+ .getSpans()+ .filter(+ (span) =>+ span.attributes?.['http.method'] === 'POST' &&+ span.attributes?.['http.target'] === actionPath &&+ span.attributes?.['next.span_type'] ===+ 'BaseServer.handleRequest'+ )+ expect(requests).toHaveLength(1)+ return requests[0]+ })+ await retry(() => {+ expect(+ getCollector()+ .getSpans()+ .filter(+ (span) =>+ span.traceId === actionRequest.traceId &&+ span.name === 'test.serverActionCompleted'+ )+ ).toHaveLength(1)+ })+ expect(loadingSpans(actionRequest.traceId)).toEqual([])+ })++ it('reports HTML loading before unused delayed Flight content finishes', async () => {+ const traceId = newTraceId()+ const id = `html-boundary-${traceId}`+ const responsePromise = next.fetch(+ `/app/test/client-component-html-boundary?id=${id}`,+ { headers: { traceparent: traceparent(traceId) } }+ )+ await gateArrivals.waitFor([id])+ const response = await responsePromise+ expect(response.status).toBe(200)++ const flush = async () => {+ const result = await next.fetch(+ '/api/app/test/client-component-flush',+ { method: 'POST' }+ )+ expect(result.status).toBe(204)+ }+ await flush()++ let html: string+ let earlySpan: SavedSpan | undefined+ try {+ // The closed panel lets HTML finish even though its unused Flight+ // child remains behind the gate.+ await retry(() => {+ const renderSpans = getCollector()+ .getSpans()+ .filter(+ (span) =>+ span.traceId === traceId &&+ span.attributes?.['next.span_type'] ===+ 'AppRender.getBodyResult'+ )+ expect(renderSpans).toHaveLength(1)+ const spans = loadingSpans(traceId)+ expect(spans).toHaveLength(1)+ earlySpan = spans[0]+ })+ expect(pendingGates.has(id)).toBe(true)+ } finally {+ releaseGate(id)+ html = await response.text()+ }++ expect(html).toContain('id="closed-panel"')+ expect(html).toContain('closed')+ expect(html).not.toContain('id="unused-client"')+ expect(earlySpan).toBeDefined()+ await flush()+ expect(loadingSpans(traceId)).toEqual([earlySpan])+ })+ })+ }+ // Edge runtime is currently not implemented in custom-entrypoint-server.ts const itEdge = useDirectEntrypointHandler ? it.skip : it @@ -197,6 +524,15 @@ describe.each( traceId: env.span.traceId, parentId: env.span.rootParentId, spans: [+ {+ attributes: {+ 'next.clientComponentLoadCount': isNextDev ? 8 : 7,+ 'next.span_type': 'NextNodeServer.clientComponentLoading',+ },+ kind: 0,+ name: 'NextNodeServer.clientComponentLoading',+ status: { code: 0 },+ }, { name: 'render route (app) /app/[param]/rsc-fetch', attributes: {@@ -277,18 +613,6 @@ describe.each( kind: 0, status: { code: 0 }, },- {- attributes: {- 'next.clientComponentLoadCount': isNextDev ? 8 : 7,- 'next.span_type':- 'NextNodeServer.clientComponentLoading',- },- kind: 0,- name: 'NextNodeServer.clientComponentLoading',- status: {- code: 0,- },- }, { name: 'start response', attributes: {@@ -894,6 +1218,15 @@ describe.each( traceId: env.span.traceId, parentId: env.span.rootParentId, spans: [+ {+ attributes: {+ 'next.clientComponentLoadCount': isNextDev ? 12 : 10,+ 'next.span_type': 'NextNodeServer.clientComponentLoading',+ },+ kind: 0,+ name: 'NextNodeServer.clientComponentLoading',+ status: { code: 0 },+ }, { name: 'render route (app) /app/[param]/rsc-fetch/error', attributes: {@@ -961,18 +1294,6 @@ describe.each( kind: 0, status: { code: 0 }, },- {- attributes: {- 'next.clientComponentLoadCount': isNextDev ? 12 : 10,- 'next.span_type':- 'NextNodeServer.clientComponentLoading',- },- kind: 0,- name: 'NextNodeServer.clientComponentLoading',- status: {- code: 0,- },- }, { name: 'start response', attributes: {@@ -1027,6 +1348,15 @@ describe.each( traceId: env.span.traceId, parentId: env.span.rootParentId, spans: [+ {+ attributes: {+ 'next.clientComponentLoadCount': isNextDev ? 9 : 8,+ 'next.span_type': 'NextNodeServer.clientComponentLoading',+ },+ kind: 0,+ name: 'NextNodeServer.clientComponentLoading',+ status: { code: 0 },+ }, { name: 'render route (app) /app/[param]/loading/error', attributes: {@@ -1089,18 +1419,6 @@ describe.each( kind: 0, status: { code: 0 }, },- {- attributes: {- 'next.clientComponentLoadCount': isNextDev ? 9 : 8,- 'next.span_type':- 'NextNodeServer.clientComponentLoading',- },- kind: 0,- name: 'NextNodeServer.clientComponentLoading',- status: {- code: 0,- },- }, { name: 'start response', attributes: {@@ -1485,6 +1803,16 @@ describe.each( }, ...(isNextDev ? [+ {+ name: 'NextNodeServer.clientComponentLoading',+ attributes: {+ 'next.clientComponentLoadCount': expect.any(Number),+ 'next.span_type':+ 'NextNodeServer.clientComponentLoading',+ },+ kind: 0,+ status: { code: 0 },+ }, { name: 'render route (app) /_not-found', attributes: {@@ -2176,6 +2504,9 @@ describe('opentelemetry with disabled fetch tracing', () => { traceId: '[trace-id]', parentId: undefined, spans: [+ {+ name: 'NextNodeServer.clientComponentLoading',+ }, { name: 'render route (app) /app/[param]/rsc-fetch', spans: [@@ -2196,9 +2527,6 @@ describe('opentelemetry with disabled fetch tracing', () => { { name: 'generateMetadata /app/[param]/rsc-fetch/page', },- {- name: 'NextNodeServer.clientComponentLoading',- }, { name: 'start response', },@@ -2266,6 +2594,15 @@ describe('opentelemetry with custom server', () => { kind: 1, status: { code: 0 }, spans: [+ {+ attributes: {+ 'next.clientComponentLoadCount': isNextDev ? 8 : 7,+ 'next.span_type': 'NextNodeServer.clientComponentLoading',+ },+ kind: 0,+ name: 'NextNodeServer.clientComponentLoading',+ status: { code: 0 },+ }, { name: 'render route (app) /app/[param]/rsc-fetch', attributes: {@@ -2342,17 +2679,6 @@ describe('opentelemetry with custom server', () => { kind: 0, status: { code: 0 }, },- {- attributes: {- 'next.clientComponentLoadCount': isNextDev ? 8 : 7,- 'next.span_type': 'NextNodeServer.clientComponentLoading',- },- kind: 0,- name: 'NextNodeServer.clientComponentLoading',- status: {- code: 0,- },- }, { name: 'start response', attributes: {