Skip to content

Commit

Permalink
[Flight] Track Timing Information (facebook#31716)
Browse files Browse the repository at this point in the history 
Stacked on facebook#31715.

This adds profiling data for Server Components to the RSC stream (but
doesn't yet use it for anything). This is on behind
`enableProfilerTimer` which is on for Dev and Profiling builds. However,
for now there's no Profiling build of Flight so in practice only in DEV.
It's gated on `enableComponentPerformanceTrack` which is experimental
only for now.

We first emit a timeOrigin in the beginning of the stream. This provides
us a relative time to emit timestamps against for cross environment
transfer so that we can log it in terms of absolute times. Using this as
a separate field allows the actual relative timestamps to be a bit more
compact representation and preserves floating point precision.

We emit a timestamp before emitting a Server Component which represents
the start time of the Server Component. The end time is either when the
next Server Component starts or when we finish the task.

We omit the end time for simple tasks that are outlined without Server
Components.

By encoding this as part of the debugInfo stream, this information can
be forwarded between Server to Server RSC.
  • Loading branch information
@sebmarkbage
sebmarkbage authored Dec 11, 2024
1 parent 7c4a7c9 commit 79ddf5b
Show file tree
Hide file tree
Showing 4 changed files with 209 additions and 38 deletions.
29 changes: 29 additions & 0 deletions packages/react-client/src/ReactFlightClient.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -48,6 +48,8 @@ import {
enableFlightReadableStream,
enableOwnerStacks,
enableServerComponentLogs,
enableProfilerTimer,
enableComponentPerformanceTrack,
} from 'shared/ReactFeatureFlags';

import {
Expand Down Expand Up @@ -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<Uint8Array>, // 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
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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 =
Expand Down Expand Up @@ -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<
Expand Down
56 changes: 50 additions & 6 deletions packages/react-client/src/__tests__/ReactFlight-test.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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');
Expand Down Expand Up @@ -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 (
Expand All @@ -300,6 +315,7 @@ describe('ReactFlight', () => {
expect(getDebugInfo(greeting)).toEqual(
__DEV__
? [
{time: 11},
{
name: 'Greeting',
env: 'Server',
Expand All @@ -313,6 +329,7 @@ describe('ReactFlight', () => {
lastName: 'Smith',
},
},
{time: 12},
]
: undefined,
);
Expand All @@ -322,6 +339,7 @@ describe('ReactFlight', () => {
expect(ReactNoop).toMatchRenderedOutput(<span>Hello, Seb Smith</span>);
});

// @gate !__DEV__ || enableComponentPerformanceTrack
it('can render a shared forwardRef Component', async () => {
const Greeting = React.forwardRef(function Greeting(
{firstName, lastName},
Expand All @@ -343,6 +361,7 @@ describe('ReactFlight', () => {
expect(getDebugInfo(promise)).toEqual(
__DEV__
? [
{time: 11},
{
name: 'Greeting',
env: 'Server',
Expand All @@ -356,6 +375,7 @@ describe('ReactFlight', () => {
lastName: 'Smith',
},
},
{time: 12},
]
: undefined,
);
Expand Down Expand Up @@ -2659,6 +2679,7 @@ describe('ReactFlight', () => {
);
});

// @gate !__DEV__ || enableComponentPerformanceTrack
it('preserves debug info for server-to-server pass through', async () => {
function ThirdPartyLazyComponent() {
return <span>!</span>;
Expand Down Expand Up @@ -2705,6 +2726,7 @@ describe('ReactFlight', () => {
expect(getDebugInfo(promise)).toEqual(
__DEV__
? [
{time: 18},
{
name: 'ServerComponent',
env: 'Server',
Expand All @@ -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',
Expand All @@ -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',
Expand All @@ -2752,12 +2780,14 @@ describe('ReactFlight', () => {
: undefined,
props: {},
},
{time: 16},
]
: undefined,
);
expect(getDebugInfo(thirdPartyChildren[2])).toEqual(
__DEV__
? [
{time: 11},
{
name: 'ThirdPartyFragmentComponent',
env: 'third-party',
Expand All @@ -2768,6 +2798,7 @@ describe('ReactFlight', () => {
: undefined,
props: {},
},
{time: 12},
]
: undefined,
);
Expand Down Expand Up @@ -2833,6 +2864,7 @@ describe('ReactFlight', () => {
expect(getDebugInfo(promise)).toEqual(
__DEV__
? [
{time: 14},
{
name: 'ServerComponent',
env: 'Server',
Expand All @@ -2845,6 +2877,7 @@ describe('ReactFlight', () => {
transport: expect.arrayContaining([]),
},
},
{time: 15},
]
: undefined,
);
Expand All @@ -2853,6 +2886,7 @@ describe('ReactFlight', () => {
expect(getDebugInfo(thirdPartyFragment)).toEqual(
__DEV__
? [
{time: 16},
{
name: 'Keyed',
env: 'Server',
Expand All @@ -2865,13 +2899,15 @@ describe('ReactFlight', () => {
children: {},
},
},
{time: 17},
]
: undefined,
);
// We expect the debug info to be transferred from the inner stream to the outer.
expect(getDebugInfo(thirdPartyFragment.props.children)).toEqual(
__DEV__
? [
{time: 11},
{
name: 'ThirdPartyAsyncIterableComponent',
env: 'third-party',
Expand All @@ -2882,6 +2918,7 @@ describe('ReactFlight', () => {
: undefined,
props: {},
},
{time: 12},
]
: undefined,
);
Expand Down Expand Up @@ -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) {
Expand All @@ -3041,6 +3079,7 @@ describe('ReactFlight', () => {
expect(getDebugInfo(greeting)).toEqual(
__DEV__
? [
{time: 11},
{
name: 'Component',
env: 'A',
Expand All @@ -3054,6 +3093,7 @@ describe('ReactFlight', () => {
{
env: 'B',
},
{time: 12},
]
: undefined,
);
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -3244,7 +3285,9 @@ describe('ReactFlight', () => {
},
};
expect(getDebugInfo(greeting)).toEqual([
{time: 11},
greetInfo,
{time: 12},
{
name: 'Container',
env: 'Server',
Expand All @@ -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);
Expand Down Expand Up @@ -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) {
Expand All @@ -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);
Expand All @@ -3564,7 +3608,7 @@ describe('ReactFlight', () => {
expect(ReactNoop).toMatchRenderedOutput(<div>not using props</div>);
});

// @gate __DEV__
// @gate __DEV__ && enableComponentPerformanceTrack
it('can render deep but cut off Map/Set in debug info', async () => {
function createDeepMap(n) {
if (n <= 0) {
Expand Down Expand Up @@ -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
Expand Down
Loading

0 comments on commit 79ddf5b

Please sign in to comment.