diff --git a/packages/react-client/src/ReactFlightClient.js b/packages/react-client/src/ReactFlightClient.js index b1479a076a1d9..19b1285ad9732 100644 --- a/packages/react-client/src/ReactFlightClient.js +++ b/packages/react-client/src/ReactFlightClient.js @@ -48,6 +48,8 @@ import { enableFlightReadableStream, enableOwnerStacks, enableServerComponentLogs, + enableProfilerTimer, + enableComponentPerformanceTrack, } from 'shared/ReactFeatureFlags'; import { @@ -286,6 +288,7 @@ export type Response = { _rowLength: number, // remaining bytes in the row. 0 indicates that we're looking for a newline. _buffer: Array, // chunks received so far as part of this row _tempRefs: void | TemporaryReferenceSet, // the set temporary references can be resolved from + _timeOrigin: number, // Profiling-only _debugRootOwner?: null | ReactComponentInfo, // DEV-only _debugRootStack?: null | Error, // DEV-only _debugRootTask?: null | ConsoleTask, // DEV-only @@ -1585,6 +1588,9 @@ function ResponseInstance( this._rowLength = 0; this._buffer = []; this._tempRefs = temporaryReferences; + if (enableProfilerTimer && enableComponentPerformanceTrack) { + this._timeOrigin = 0; + } if (__DEV__) { // TODO: The Flight Client can be used in a Client Environment too and we should really support // getting the owner there as well, but currently the owner of ReactComponentInfo is typed as only @@ -2512,6 +2518,16 @@ function resolveDebugInfo( debugInfo; initializeFakeStack(response, componentInfoOrAsyncInfo); } + if (enableProfilerTimer && enableComponentPerformanceTrack) { + if (typeof debugInfo.time === 'number') { + // Adjust the time to the current environment's time space. + // Since this might be a deduped object, we clone it to avoid + // applying the adjustment twice. + debugInfo = { + time: debugInfo.time + response._timeOrigin, + }; + } + } const chunk = getChunk(response, id); const chunkDebugInfo: ReactDebugInfo = @@ -2792,6 +2808,19 @@ function processFullStringRow( resolveText(response, id, row); return; } + case 78 /* "N" */: { + if (enableProfilerTimer && enableComponentPerformanceTrack) { + // Track the time origin for future debug info. We track it relative + // to the current environment's time space. + const timeOrigin: number = +row; + response._timeOrigin = + timeOrigin - + // $FlowFixMe[prop-missing] + performance.timeOrigin; + return; + } + // Fallthrough to share the error with Debug and Console entries. + } case 68 /* "D" */: { if (__DEV__) { const chunk: ResolvedModelChunk< diff --git a/packages/react-client/src/__tests__/ReactFlight-test.js b/packages/react-client/src/__tests__/ReactFlight-test.js index dc33d03f94261..75220b762918e 100644 --- a/packages/react-client/src/__tests__/ReactFlight-test.js +++ b/packages/react-client/src/__tests__/ReactFlight-test.js @@ -125,6 +125,20 @@ let assertConsoleErrorDev; describe('ReactFlight', () => { beforeEach(() => { + // Mock performance.now for timing tests + let time = 10; + const now = jest.fn().mockImplementation(() => { + return time++; + }); + Object.defineProperty(performance, 'timeOrigin', { + value: time, + configurable: true, + }); + Object.defineProperty(performance, 'now', { + value: now, + configurable: true, + }); + jest.resetModules(); jest.mock('react', () => require('react/react.react-server')); ReactServer = require('react'); @@ -274,6 +288,7 @@ describe('ReactFlight', () => { }); }); + // @gate !__DEV__ || enableComponentPerformanceTrack it('can render a Client Component using a module reference and render there', async () => { function UserClient(props) { return ( @@ -300,6 +315,7 @@ describe('ReactFlight', () => { expect(getDebugInfo(greeting)).toEqual( __DEV__ ? [ + {time: 11}, { name: 'Greeting', env: 'Server', @@ -313,6 +329,7 @@ describe('ReactFlight', () => { lastName: 'Smith', }, }, + {time: 12}, ] : undefined, ); @@ -322,6 +339,7 @@ describe('ReactFlight', () => { expect(ReactNoop).toMatchRenderedOutput(Hello, Seb Smith); }); + // @gate !__DEV__ || enableComponentPerformanceTrack it('can render a shared forwardRef Component', async () => { const Greeting = React.forwardRef(function Greeting( {firstName, lastName}, @@ -343,6 +361,7 @@ describe('ReactFlight', () => { expect(getDebugInfo(promise)).toEqual( __DEV__ ? [ + {time: 11}, { name: 'Greeting', env: 'Server', @@ -356,6 +375,7 @@ describe('ReactFlight', () => { lastName: 'Smith', }, }, + {time: 12}, ] : undefined, ); @@ -2659,6 +2679,7 @@ describe('ReactFlight', () => { ); }); + // @gate !__DEV__ || enableComponentPerformanceTrack it('preserves debug info for server-to-server pass through', async () => { function ThirdPartyLazyComponent() { return !; @@ -2705,6 +2726,7 @@ describe('ReactFlight', () => { expect(getDebugInfo(promise)).toEqual( __DEV__ ? [ + {time: 18}, { name: 'ServerComponent', env: 'Server', @@ -2717,15 +2739,18 @@ describe('ReactFlight', () => { transport: expect.arrayContaining([]), }, }, + {time: 19}, ] : undefined, ); const result = await promise; + const thirdPartyChildren = await result.props.children[1]; // We expect the debug info to be transferred from the inner stream to the outer. expect(getDebugInfo(thirdPartyChildren[0])).toEqual( __DEV__ ? [ + {time: 13}, { name: 'ThirdPartyComponent', env: 'third-party', @@ -2736,12 +2761,15 @@ describe('ReactFlight', () => { : undefined, props: {}, }, + {time: 14}, + {time: 21}, // This last one is when the promise resolved into the first party. ] : undefined, ); expect(getDebugInfo(thirdPartyChildren[1])).toEqual( __DEV__ ? [ + {time: 15}, { name: 'ThirdPartyLazyComponent', env: 'third-party', @@ -2752,12 +2780,14 @@ describe('ReactFlight', () => { : undefined, props: {}, }, + {time: 16}, ] : undefined, ); expect(getDebugInfo(thirdPartyChildren[2])).toEqual( __DEV__ ? [ + {time: 11}, { name: 'ThirdPartyFragmentComponent', env: 'third-party', @@ -2768,6 +2798,7 @@ describe('ReactFlight', () => { : undefined, props: {}, }, + {time: 12}, ] : undefined, ); @@ -2833,6 +2864,7 @@ describe('ReactFlight', () => { expect(getDebugInfo(promise)).toEqual( __DEV__ ? [ + {time: 14}, { name: 'ServerComponent', env: 'Server', @@ -2845,6 +2877,7 @@ describe('ReactFlight', () => { transport: expect.arrayContaining([]), }, }, + {time: 15}, ] : undefined, ); @@ -2853,6 +2886,7 @@ describe('ReactFlight', () => { expect(getDebugInfo(thirdPartyFragment)).toEqual( __DEV__ ? [ + {time: 16}, { name: 'Keyed', env: 'Server', @@ -2865,6 +2899,7 @@ describe('ReactFlight', () => { children: {}, }, }, + {time: 17}, ] : undefined, ); @@ -2872,6 +2907,7 @@ describe('ReactFlight', () => { expect(getDebugInfo(thirdPartyFragment.props.children)).toEqual( __DEV__ ? [ + {time: 11}, { name: 'ThirdPartyAsyncIterableComponent', env: 'third-party', @@ -2882,6 +2918,7 @@ describe('ReactFlight', () => { : undefined, props: {}, }, + {time: 12}, ] : undefined, ); @@ -3017,6 +3054,7 @@ describe('ReactFlight', () => { } }); + // @gate !__DEV__ || enableComponentPerformanceTrack it('can change the environment name inside a component', async () => { let env = 'A'; function Component(props) { @@ -3041,6 +3079,7 @@ describe('ReactFlight', () => { expect(getDebugInfo(greeting)).toEqual( __DEV__ ? [ + {time: 11}, { name: 'Component', env: 'A', @@ -3054,6 +3093,7 @@ describe('ReactFlight', () => { { env: 'B', }, + {time: 12}, ] : undefined, ); @@ -3205,6 +3245,7 @@ describe('ReactFlight', () => { ); }); + // @gate !__DEV__ || enableComponentPerformanceTrack it('uses the server component debug info as the element owner in DEV', async () => { function Container({children}) { return children; @@ -3244,7 +3285,9 @@ describe('ReactFlight', () => { }, }; expect(getDebugInfo(greeting)).toEqual([ + {time: 11}, greetInfo, + {time: 12}, { name: 'Container', env: 'Server', @@ -3262,10 +3305,11 @@ describe('ReactFlight', () => { }), }, }, + {time: 13}, ]); // The owner that created the span was the outer server component. // We expect the debug info to be referentially equal to the owner. - expect(greeting._owner).toBe(greeting._debugInfo[0]); + expect(greeting._owner).toBe(greeting._debugInfo[1]); } else { expect(greeting._debugInfo).toBe(undefined); expect(greeting._owner).toBe(undefined); @@ -3531,7 +3575,7 @@ describe('ReactFlight', () => { expect(caughtError.digest).toBe('digest("my-error")'); }); - // @gate __DEV__ + // @gate __DEV__ && enableComponentPerformanceTrack it('can render deep but cut off JSX in debug info', async () => { function createDeepJSX(n) { if (n <= 0) { @@ -3555,7 +3599,7 @@ describe('ReactFlight', () => { await act(async () => { const rootModel = await ReactNoopFlightClient.read(transport); const root = rootModel.root; - const children = root._debugInfo[0].props.children; + const children = root._debugInfo[1].props.children; expect(children.type).toBe('div'); expect(children.props.children.type).toBe('div'); ReactNoop.render(root); @@ -3564,7 +3608,7 @@ describe('ReactFlight', () => { expect(ReactNoop).toMatchRenderedOutput(
not using props
); }); - // @gate __DEV__ + // @gate __DEV__ && enableComponentPerformanceTrack it('can render deep but cut off Map/Set in debug info', async () => { function createDeepMap(n) { if (n <= 0) { @@ -3603,8 +3647,8 @@ describe('ReactFlight', () => { await act(async () => { const rootModel = await ReactNoopFlightClient.read(transport); - const set = rootModel.set._debugInfo[0].props.set; - const map = rootModel.map._debugInfo[0].props.map; + const set = rootModel.set._debugInfo[1].props.set; + const map = rootModel.map._debugInfo[1].props.map; expect(set instanceof Set).toBe(true); expect(set.size).toBe(1); // eslint-disable-next-line no-for-of-loops/no-for-of-loops diff --git a/packages/react-server-dom-webpack/src/__tests__/ReactFlightDOMEdge-test.js b/packages/react-server-dom-webpack/src/__tests__/ReactFlightDOMEdge-test.js index 947133149aef7..e702ae8f8e84f 100644 --- a/packages/react-server-dom-webpack/src/__tests__/ReactFlightDOMEdge-test.js +++ b/packages/react-server-dom-webpack/src/__tests__/ReactFlightDOMEdge-test.js @@ -49,6 +49,20 @@ function normalizeCodeLocInfo(str) { describe('ReactFlightDOMEdge', () => { beforeEach(() => { + // Mock performance.now for timing tests + let time = 10; + const now = jest.fn().mockImplementation(() => { + return time++; + }); + Object.defineProperty(performance, 'timeOrigin', { + value: time, + configurable: true, + }); + Object.defineProperty(performance, 'now', { + value: now, + configurable: true, + }); + jest.resetModules(); reactServerAct = require('internal-test-utils').serverAct; @@ -401,7 +415,7 @@ describe('ReactFlightDOMEdge', () => { const serializedContent = await readResult(stream1); - expect(serializedContent.length).toBeLessThan(425); + expect(serializedContent.length).toBeLessThan(490); expect(timesRendered).toBeLessThan(5); const model = await ReactServerDOMClient.createFromReadableStream(stream2, { @@ -472,7 +486,7 @@ describe('ReactFlightDOMEdge', () => { const [stream1, stream2] = passThrough(stream).tee(); const serializedContent = await readResult(stream1); - expect(serializedContent.length).toBeLessThan(__DEV__ ? 605 : 400); + expect(serializedContent.length).toBeLessThan(__DEV__ ? 680 : 400); expect(timesRendered).toBeLessThan(5); const model = await serverAct(() => @@ -506,7 +520,7 @@ describe('ReactFlightDOMEdge', () => { ), ); const serializedContent = await readResult(stream); - const expectedDebugInfoSize = __DEV__ ? 300 * 20 : 0; + const expectedDebugInfoSize = __DEV__ ? 320 * 20 : 0; expect(serializedContent.length).toBeLessThan(150 + expectedDebugInfoSize); }); @@ -934,6 +948,7 @@ describe('ReactFlightDOMEdge', () => { ); }); + // @gate !__DEV__ || enableComponentPerformanceTrack it('supports async server component debug info as the element owner in DEV', async () => { function Container({children}) { return children; @@ -989,16 +1004,19 @@ describe('ReactFlightDOMEdge', () => { owner: null, }); expect(lazyWrapper._debugInfo).toEqual([ + {time: 11}, greetInfo, + {time: 12}, expect.objectContaining({ name: 'Container', env: 'Server', owner: greetInfo, }), + {time: 13}, ]); // The owner that created the span was the outer server component. // We expect the debug info to be referentially equal to the owner. - expect(greeting._owner).toBe(lazyWrapper._debugInfo[0]); + expect(greeting._owner).toBe(lazyWrapper._debugInfo[1]); } else { expect(lazyWrapper._debugInfo).toBe(undefined); expect(greeting._owner).toBe(undefined); diff --git a/packages/react-server/src/ReactFlightServer.js b/packages/react-server/src/ReactFlightServer.js index 2f25fe318aade..860ff3cd0d898 100644 --- a/packages/react-server/src/ReactFlightServer.js +++ b/packages/react-server/src/ReactFlightServer.js @@ -20,6 +20,8 @@ import { enableTaint, enableServerComponentLogs, enableOwnerStacks, + enableProfilerTimer, + enableComponentPerformanceTrack, } from 'shared/ReactFeatureFlags'; import {enableFlightReadableStream} from 'shared/ReactFeatureFlags'; @@ -345,6 +347,7 @@ type Task = { keyPath: null | string, // parent server component keys implicitSlot: boolean, // true if the root server component of this sequence had a null key thenableState: ThenableState | null, + timed: boolean, // Profiling-only. Whether we need to track the completion time of this task. environmentName: string, // DEV-only. Used to track if the environment for this task changed. debugOwner: null | ReactComponentInfo, // DEV-only debugStack: null | Error, // DEV-only @@ -392,6 +395,8 @@ export type Request = { onPostpone: (reason: string) => void, onAllReady: () => void, onFatalError: mixed => void, + // Profiling-only + timeOrigin: number, // DEV-only environmentName: () => string, filterStackFrame: (url: string, functionName: string) => boolean, @@ -517,6 +522,23 @@ function RequestInstance( : filterStackFrame; this.didWarnForKey = null; } + + if (enableProfilerTimer && enableComponentPerformanceTrack) { + // We start by serializing the time origin. Any future timestamps will be + // emitted relatively to this origin. Instead of using performance.timeOrigin + // as this origin, we use the timestamp at the start of the request. + // This avoids leaking unnecessary information like how long the server has + // been running and allows for more compact representation of each timestamp. + // The time origin is stored as an offset in the time space of this environment. + const timeOrigin = (this.timeOrigin = performance.now()); + emitTimeOriginChunk( + this, + timeOrigin + + // $FlowFixMe[prop-missing] + performance.timeOrigin, + ); + } + const rootTask = createTask( this, model, @@ -690,6 +712,11 @@ function serializeThenable( }, ); + if (enableProfilerTimer && enableComponentPerformanceTrack) { + // If this is async we need to time when this task finishes. + newTask.timed = true; + } + return newTask.id; } @@ -1240,6 +1267,13 @@ function renderFunctionComponent( // being no references to this as an owner. outlineComponentInfo(request, componentDebugInfo); + + // Track when we started rendering this component. + if (enableProfilerTimer && enableComponentPerformanceTrack) { + task.timed = true; + emitTimingChunk(request, componentDebugID, performance.now()); + } + emitDebugChunk(request, componentDebugID, componentDebugInfo); // We've emitted the latest environment for this task so we track that. @@ -1769,6 +1803,10 @@ function renderElement( } function pingTask(request: Request, task: Task): void { + if (enableProfilerTimer && enableComponentPerformanceTrack) { + // If this was async we need to emit the time when it completes. + task.timed = true; + } const pingedTasks = request.pingedTasks; pingedTasks.push(task); if (pingedTasks.length === 1) { @@ -1862,8 +1900,11 @@ function createTask( thenableState: null, }: Omit< Task, - 'environmentName' | 'debugOwner' | 'debugStack' | 'debugTask', + 'timed' | 'environmentName' | 'debugOwner' | 'debugStack' | 'debugTask', >): any); + if (enableProfilerTimer && enableComponentPerformanceTrack) { + task.timed = false; + } if (__DEV__) { task.environmentName = request.environmentName(); task.debugOwner = debugOwner; @@ -3769,6 +3810,17 @@ function emitConsoleChunk( request.completedRegularChunks.push(processedChunk); } +function emitTimeOriginChunk(request: Request, timeOrigin: number): void { + // We emit the time origin once. All ReactTimeInfo timestamps later in the stream + // are relative to this time origin. This allows for more compact number encoding + // and lower precision loss. + request.pendingChunks++; + const row = ':N' + timeOrigin + '\n'; + const processedChunk = stringToChunk(row); + // TODO: Move to its own priority queue. + request.completedRegularChunks.push(processedChunk); +} + function forwardDebugInfo( request: Request, id: number, @@ -3776,16 +3828,38 @@ function forwardDebugInfo( ) { for (let i = 0; i < debugInfo.length; i++) { request.pendingChunks++; - if (typeof debugInfo[i].name === 'string') { - // We outline this model eagerly so that we can refer to by reference as an owner. - // If we had a smarter way to dedupe we might not have to do this if there ends up - // being no references to this as an owner. - outlineComponentInfo(request, (debugInfo[i]: any)); + if (typeof debugInfo[i].time === 'number') { + // When forwarding time we need to ensure to convert it to the time space of the payload. + emitTimingChunk(request, id, debugInfo[i].time); + } else { + if (typeof debugInfo[i].name === 'string') { + // We outline this model eagerly so that we can refer to by reference as an owner. + // If we had a smarter way to dedupe we might not have to do this if there ends up + // being no references to this as an owner. + outlineComponentInfo(request, (debugInfo[i]: any)); + } + emitDebugChunk(request, id, debugInfo[i]); } - emitDebugChunk(request, id, debugInfo[i]); } } +function emitTimingChunk( + request: Request, + id: number, + timestamp: number, +): void { + if (!enableProfilerTimer || !enableComponentPerformanceTrack) { + return; + } + request.pendingChunks++; + const relativeTimestamp = timestamp - request.timeOrigin; + const row = + serializeRowHeader('D', id) + '{"time":' + relativeTimestamp + '}\n'; + const processedChunk = stringToChunk(row); + // TODO: Move to its own priority queue. + request.completedRegularChunks.push(processedChunk); +} + function emitChunk( request: Request, task: Task, @@ -3877,6 +3951,11 @@ function emitChunk( } function erroredTask(request: Request, task: Task, error: mixed): void { + if (enableProfilerTimer && enableComponentPerformanceTrack) { + if (task.timed) { + emitTimingChunk(request, task.id, performance.now()); + } + } request.abortableTasks.delete(task); task.status = ERRORED; if ( @@ -3939,21 +4018,27 @@ function retryTask(request: Request, task: Task): void { task.keyPath = null; task.implicitSlot = false; + if (__DEV__) { + const currentEnv = (0, request.environmentName)(); + if (currentEnv !== task.environmentName) { + request.pendingChunks++; + // The environment changed since we last emitted any debug information for this + // task. We emit an entry that just includes the environment name change. + emitDebugChunk(request, task.id, {env: currentEnv}); + } + } + // We've finished rendering. Log the end time. + if (enableProfilerTimer && enableComponentPerformanceTrack) { + if (task.timed) { + emitTimingChunk(request, task.id, performance.now()); + } + } + if (typeof resolvedModel === 'object' && resolvedModel !== null) { // We're not in a contextual place here so we can refer to this object by this ID for // any future references. request.writtenObjects.set(resolvedModel, serializeByValueID(task.id)); - if (__DEV__) { - const currentEnv = (0, request.environmentName)(); - if (currentEnv !== task.environmentName) { - request.pendingChunks++; - // The environment changed since we last emitted any debug information for this - // task. We emit an entry that just includes the environment name change. - emitDebugChunk(request, task.id, {env: currentEnv}); - } - } - // Object might contain unresolved values like additional elements. // This is simulating what the JSON loop would do if this was part of it. emitChunk(request, task, resolvedModel); @@ -3962,17 +4047,6 @@ function retryTask(request: Request, task: Task): void { // We don't need to escape it again so it's not passed the toJSON replacer. // $FlowFixMe[incompatible-type] stringify can return null for undefined but we never do const json: string = stringify(resolvedModel); - - if (__DEV__) { - const currentEnv = (0, request.environmentName)(); - if (currentEnv !== task.environmentName) { - request.pendingChunks++; - // The environment changed since we last emitted any debug information for this - // task. We emit an entry that just includes the environment name change. - emitDebugChunk(request, task.id, {env: currentEnv}); - } - } - emitModelChunk(request, task.id, json); } @@ -4082,6 +4156,12 @@ function abortTask(task: Task, request: Request, errorId: number): void { return; } task.status = ABORTED; + // Track when we aborted this task as its end time. + if (enableProfilerTimer && enableComponentPerformanceTrack) { + if (task.timed) { + emitTimingChunk(request, task.id, performance.now()); + } + } // Instead of emitting an error per task.id, we emit a model that only // has a single value referencing the error. const ref = serializeByValueID(errorId);