Skip to content

Commit 79ddf5b

Browse files
sebmarkbagesebmarkbage
authored
[Flight] Track Timing Information (facebook#31716)
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.
1 parent 7c4a7c9 commit 79ddf5b

File tree

4 files changed

+209
-38
lines changed

4 files changed

+209
-38
lines changed

‎packages/react-client/src/ReactFlightClient.js‎

Lines changed: 29 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -48,6 +48,8 @@ import {
4848
enableFlightReadableStream,
4949
enableOwnerStacks,
5050
enableServerComponentLogs,
51+
enableProfilerTimer,
52+
enableComponentPerformanceTrack,
5153
} from 'shared/ReactFeatureFlags';
5254

5355
import {
@@ -286,6 +288,7 @@ export type Response = {
286288
_rowLength: number, // remaining bytes in the row. 0 indicates that we're looking for a newline.
287289
_buffer: Array<Uint8Array>, // chunks received so far as part of this row
288290
_tempRefs: void | TemporaryReferenceSet, // the set temporary references can be resolved from
291+
_timeOrigin: number, // Profiling-only
289292
_debugRootOwner?: null | ReactComponentInfo, // DEV-only
290293
_debugRootStack?: null | Error, // DEV-only
291294
_debugRootTask?: null | ConsoleTask, // DEV-only
@@ -1585,6 +1588,9 @@ function ResponseInstance(
15851588
this._rowLength = 0;
15861589
this._buffer = [];
15871590
this._tempRefs = temporaryReferences;
1591+
if (enableProfilerTimer && enableComponentPerformanceTrack) {
1592+
this._timeOrigin = 0;
1593+
}
15881594
if (__DEV__) {
15891595
// TODO: The Flight Client can be used in a Client Environment too and we should really support
15901596
// getting the owner there as well, but currently the owner of ReactComponentInfo is typed as only
@@ -2512,6 +2518,16 @@ function resolveDebugInfo(
25122518
debugInfo;
25132519
initializeFakeStack(response, componentInfoOrAsyncInfo);
25142520
}
2521+
if (enableProfilerTimer && enableComponentPerformanceTrack) {
2522+
if (typeof debugInfo.time === 'number') {
2523+
// Adjust the time to the current environment's time space.
2524+
// Since this might be a deduped object, we clone it to avoid
2525+
// applying the adjustment twice.
2526+
debugInfo = {
2527+
time: debugInfo.time + response._timeOrigin,
2528+
};
2529+
}
2530+
}
25152531

25162532
const chunk = getChunk(response, id);
25172533
const chunkDebugInfo: ReactDebugInfo =
@@ -2792,6 +2808,19 @@ function processFullStringRow(
27922808
resolveText(response, id, row);
27932809
return;
27942810
}
2811+
case 78 /* "N" */: {
2812+
if (enableProfilerTimer && enableComponentPerformanceTrack) {
2813+
// Track the time origin for future debug info. We track it relative
2814+
// to the current environment's time space.
2815+
const timeOrigin: number = +row;
2816+
response._timeOrigin =
2817+
timeOrigin -
2818+
// $FlowFixMe[prop-missing]
2819+
performance.timeOrigin;
2820+
return;
2821+
}
2822+
// Fallthrough to share the error with Debug and Console entries.
2823+
}
27952824
case 68 /* "D" */: {
27962825
if (__DEV__) {
27972826
const chunk: ResolvedModelChunk<

‎packages/react-client/src/__tests__/ReactFlight-test.js‎

Lines changed: 50 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -125,6 +125,20 @@ let assertConsoleErrorDev;
125125

126126
describe('ReactFlight', () => {
127127
beforeEach(() => {
128+
// Mock performance.now for timing tests
129+
let time = 10;
130+
const now = jest.fn().mockImplementation(() => {
131+
return time++;
132+
});
133+
Object.defineProperty(performance, 'timeOrigin', {
134+
value: time,
135+
configurable: true,
136+
});
137+
Object.defineProperty(performance, 'now', {
138+
value: now,
139+
configurable: true,
140+
});
141+
128142
jest.resetModules();
129143
jest.mock('react', () => require('react/react.react-server'));
130144
ReactServer = require('react');
@@ -274,6 +288,7 @@ describe('ReactFlight', () => {
274288
});
275289
});
276290

291+
// @gate !__DEV__ || enableComponentPerformanceTrack
277292
it('can render a Client Component using a module reference and render there', async () => {
278293
function UserClient(props) {
279294
return (
@@ -300,6 +315,7 @@ describe('ReactFlight', () => {
300315
expect(getDebugInfo(greeting)).toEqual(
301316
__DEV__
302317
? [
318+
{time: 11},
303319
{
304320
name: 'Greeting',
305321
env: 'Server',
@@ -313,6 +329,7 @@ describe('ReactFlight', () => {
313329
lastName: 'Smith',
314330
},
315331
},
332+
{time: 12},
316333
]
317334
: undefined,
318335
);
@@ -322,6 +339,7 @@ describe('ReactFlight', () => {
322339
expect(ReactNoop).toMatchRenderedOutput(<span>Hello, Seb Smith</span>);
323340
});
324341

342+
// @gate !__DEV__ || enableComponentPerformanceTrack
325343
it('can render a shared forwardRef Component', async () => {
326344
const Greeting = React.forwardRef(function Greeting(
327345
{firstName, lastName},
@@ -343,6 +361,7 @@ describe('ReactFlight', () => {
343361
expect(getDebugInfo(promise)).toEqual(
344362
__DEV__
345363
? [
364+
{time: 11},
346365
{
347366
name: 'Greeting',
348367
env: 'Server',
@@ -356,6 +375,7 @@ describe('ReactFlight', () => {
356375
lastName: 'Smith',
357376
},
358377
},
378+
{time: 12},
359379
]
360380
: undefined,
361381
);
@@ -2659,6 +2679,7 @@ describe('ReactFlight', () => {
26592679
);
26602680
});
26612681

2682+
// @gate !__DEV__ || enableComponentPerformanceTrack
26622683
it('preserves debug info for server-to-server pass through', async () => {
26632684
function ThirdPartyLazyComponent() {
26642685
return <span>!</span>;
@@ -2705,6 +2726,7 @@ describe('ReactFlight', () => {
27052726
expect(getDebugInfo(promise)).toEqual(
27062727
__DEV__
27072728
? [
2729+
{time: 18},
27082730
{
27092731
name: 'ServerComponent',
27102732
env: 'Server',
@@ -2717,15 +2739,18 @@ describe('ReactFlight', () => {
27172739
transport: expect.arrayContaining([]),
27182740
},
27192741
},
2742+
{time: 19},
27202743
]
27212744
: undefined,
27222745
);
27232746
const result = await promise;
2747+
27242748
const thirdPartyChildren = await result.props.children[1];
27252749
// We expect the debug info to be transferred from the inner stream to the outer.
27262750
expect(getDebugInfo(thirdPartyChildren[0])).toEqual(
27272751
__DEV__
27282752
? [
2753+
{time: 13},
27292754
{
27302755
name: 'ThirdPartyComponent',
27312756
env: 'third-party',
@@ -2736,12 +2761,15 @@ describe('ReactFlight', () => {
27362761
: undefined,
27372762
props: {},
27382763
},
2764+
{time: 14},
2765+
{time: 21}, // This last one is when the promise resolved into the first party.
27392766
]
27402767
: undefined,
27412768
);
27422769
expect(getDebugInfo(thirdPartyChildren[1])).toEqual(
27432770
__DEV__
27442771
? [
2772+
{time: 15},
27452773
{
27462774
name: 'ThirdPartyLazyComponent',
27472775
env: 'third-party',
@@ -2752,12 +2780,14 @@ describe('ReactFlight', () => {
27522780
: undefined,
27532781
props: {},
27542782
},
2783+
{time: 16},
27552784
]
27562785
: undefined,
27572786
);
27582787
expect(getDebugInfo(thirdPartyChildren[2])).toEqual(
27592788
__DEV__
27602789
? [
2790+
{time: 11},
27612791
{
27622792
name: 'ThirdPartyFragmentComponent',
27632793
env: 'third-party',
@@ -2768,6 +2798,7 @@ describe('ReactFlight', () => {
27682798
: undefined,
27692799
props: {},
27702800
},
2801+
{time: 12},
27712802
]
27722803
: undefined,
27732804
);
@@ -2833,6 +2864,7 @@ describe('ReactFlight', () => {
28332864
expect(getDebugInfo(promise)).toEqual(
28342865
__DEV__
28352866
? [
2867+
{time: 14},
28362868
{
28372869
name: 'ServerComponent',
28382870
env: 'Server',
@@ -2845,6 +2877,7 @@ describe('ReactFlight', () => {
28452877
transport: expect.arrayContaining([]),
28462878
},
28472879
},
2880+
{time: 15},
28482881
]
28492882
: undefined,
28502883
);
@@ -2853,6 +2886,7 @@ describe('ReactFlight', () => {
28532886
expect(getDebugInfo(thirdPartyFragment)).toEqual(
28542887
__DEV__
28552888
? [
2889+
{time: 16},
28562890
{
28572891
name: 'Keyed',
28582892
env: 'Server',
@@ -2865,13 +2899,15 @@ describe('ReactFlight', () => {
28652899
children: {},
28662900
},
28672901
},
2902+
{time: 17},
28682903
]
28692904
: undefined,
28702905
);
28712906
// We expect the debug info to be transferred from the inner stream to the outer.
28722907
expect(getDebugInfo(thirdPartyFragment.props.children)).toEqual(
28732908
__DEV__
28742909
? [
2910+
{time: 11},
28752911
{
28762912
name: 'ThirdPartyAsyncIterableComponent',
28772913
env: 'third-party',
@@ -2882,6 +2918,7 @@ describe('ReactFlight', () => {
28822918
: undefined,
28832919
props: {},
28842920
},
2921+
{time: 12},
28852922
]
28862923
: undefined,
28872924
);
@@ -3017,6 +3054,7 @@ describe('ReactFlight', () => {
30173054
}
30183055
});
30193056

3057+
// @gate !__DEV__ || enableComponentPerformanceTrack
30203058
it('can change the environment name inside a component', async () => {
30213059
let env = 'A';
30223060
function Component(props) {
@@ -3041,6 +3079,7 @@ describe('ReactFlight', () => {
30413079
expect(getDebugInfo(greeting)).toEqual(
30423080
__DEV__
30433081
? [
3082+
{time: 11},
30443083
{
30453084
name: 'Component',
30463085
env: 'A',
@@ -3054,6 +3093,7 @@ describe('ReactFlight', () => {
30543093
{
30553094
env: 'B',
30563095
},
3096+
{time: 12},
30573097
]
30583098
: undefined,
30593099
);
@@ -3205,6 +3245,7 @@ describe('ReactFlight', () => {
32053245
);
32063246
});
32073247

3248+
// @gate !__DEV__ || enableComponentPerformanceTrack
32083249
it('uses the server component debug info as the element owner in DEV', async () => {
32093250
function Container({children}) {
32103251
return children;
@@ -3244,7 +3285,9 @@ describe('ReactFlight', () => {
32443285
},
32453286
};
32463287
expect(getDebugInfo(greeting)).toEqual([
3288+
{time: 11},
32473289
greetInfo,
3290+
{time: 12},
32483291
{
32493292
name: 'Container',
32503293
env: 'Server',
@@ -3262,10 +3305,11 @@ describe('ReactFlight', () => {
32623305
}),
32633306
},
32643307
},
3308+
{time: 13},
32653309
]);
32663310
// The owner that created the span was the outer server component.
32673311
// We expect the debug info to be referentially equal to the owner.
3268-
expect(greeting._owner).toBe(greeting._debugInfo[0]);
3312+
expect(greeting._owner).toBe(greeting._debugInfo[1]);
32693313
} else {
32703314
expect(greeting._debugInfo).toBe(undefined);
32713315
expect(greeting._owner).toBe(undefined);
@@ -3531,7 +3575,7 @@ describe('ReactFlight', () => {
35313575
expect(caughtError.digest).toBe('digest("my-error")');
35323576
});
35333577

3534-
// @gate __DEV__
3578+
// @gate __DEV__ && enableComponentPerformanceTrack
35353579
it('can render deep but cut off JSX in debug info', async () => {
35363580
function createDeepJSX(n) {
35373581
if (n <= 0) {
@@ -3555,7 +3599,7 @@ describe('ReactFlight', () => {
35553599
await act(async () => {
35563600
const rootModel = await ReactNoopFlightClient.read(transport);
35573601
const root = rootModel.root;
3558-
const children = root._debugInfo[0].props.children;
3602+
const children = root._debugInfo[1].props.children;
35593603
expect(children.type).toBe('div');
35603604
expect(children.props.children.type).toBe('div');
35613605
ReactNoop.render(root);
@@ -3564,7 +3608,7 @@ describe('ReactFlight', () => {
35643608
expect(ReactNoop).toMatchRenderedOutput(<div>not using props</div>);
35653609
});
35663610

3567-
// @gate __DEV__
3611+
// @gate __DEV__ && enableComponentPerformanceTrack
35683612
it('can render deep but cut off Map/Set in debug info', async () => {
35693613
function createDeepMap(n) {
35703614
if (n <= 0) {
@@ -3603,8 +3647,8 @@ describe('ReactFlight', () => {
36033647

36043648
await act(async () => {
36053649
const rootModel = await ReactNoopFlightClient.read(transport);
3606-
const set = rootModel.set._debugInfo[0].props.set;
3607-
const map = rootModel.map._debugInfo[0].props.map;
3650+
const set = rootModel.set._debugInfo[1].props.set;
3651+
const map = rootModel.map._debugInfo[1].props.map;
36083652
expect(set instanceof Set).toBe(true);
36093653
expect(set.size).toBe(1);
36103654
// eslint-disable-next-line no-for-of-loops/no-for-of-loops

0 commit comments

Comments
 (0)