[Flight] Emit the time we awaited something inside a Server Component (#33402)
Stacked on #33400. <img width="1261" alt="Screenshot 2025-06-01 at 10 27 47 PM" src="https://github.com/user-attachments/assets/a5a73ee2-49e0-4851-84ac-e0df6032efb5" /> This is emitted with the start/end time and stack of the "await". Which may be different than the thing that started the I/O. These awaits aren't quite as simple as just every await since you can start a sequence in parallel there can actually be multiple overlapping awaits and there can be CPU work interleaved with the await on the same component. ```js function getData() { await fetch(...); await fetch(...); } const promise = getData(); doWork(); await promise; ``` This has two "I/O" awaits but those are actually happening in parallel with `doWork()`. Since these also could have started before we started rendering this sequence (e.g. a component) we have to clamp it so that we don't consider awaits that start before the component. What we're conceptually trying to convey is the time this component was blocked due to that I/O resource. Whether it's blocked from completing the last result or if it's blocked from issuing a waterfall request.
Sebastian Markbåge committed
Jun 3, 2025 at 17:29 UTC
9cc74fec749bcca2e0f5d1e41aa612b2135641ff
6 files changed
+138
-19
packages/react-client/src/ReactFlightClient.js
+29
-4
@@ -79,6 +79,7 @@ import {
79
logDedupedComponentRender,
80
logComponentErrored,
81
logIOInfo,
82
+ logComponentAwait,
83
} from './ReactFlightPerformanceTrack';
84
85
import {
@@ -680,7 +681,7 @@ function getIOInfoTaskName(ioInfo: ReactIOInfo): string {
681
}
682
683
function getAsyncInfoTaskName(asyncInfo: ReactAsyncInfo): string {
683
- return 'await'; // We could be smarter about this and give it a name like `then` or `Promise.all`.
684
+ return 'await ' + getIOInfoTaskName(asyncInfo.awaited);
685
}
686
687
function getServerComponentTaskName(componentInfo: ReactComponentInfo): string {
@@ -2971,9 +2972,12 @@ function flushComponentPerformance(
2972
for (let i = debugInfo.length - 1; i >= 0; i--) {
2973
const info = debugInfo[i];
2974
if (typeof info.time === 'number') {
2974
- endTime = info.time;
2975
- if (endTime > childrenEndTime) {
2976
- childrenEndTime = endTime;
2975
+ if (info.time > childrenEndTime) {
2976
+ childrenEndTime = info.time;
2977
+ }
2978
+ if (endTime === 0) {
2979
+ // Last timestamp is the end of the last component.
2980
+ endTime = info.time;
2981
}
2982
}
2983
if (typeof info.name === 'string' && i > 0) {
@@ -3011,8 +3015,29 @@ function flushComponentPerformance(
3015
}
3016
// Track the root most component of the result for deduping logging.
3017
result.component = componentInfo;
3018
+ // Set the end time of the previous component to the start of the previous.
3019
+ endTime = startTime;
3020
}
3021
isLastComponent = false;
3022
+ } else if (info.awaited && i > 0 && i < debugInfo.length - 2) {
3023
+ // $FlowFixMe: Refined.
3024
+ const asyncInfo: ReactAsyncInfo = info;
3025
+ const startTimeInfo = debugInfo[i - 1];
3026
+ const endTimeInfo = debugInfo[i + 1];
3027
+ if (
3028
+ typeof startTimeInfo.time === 'number' &&
3029
+ typeof endTimeInfo.time === 'number'
3030
+ ) {
3031
+ const awaitStartTime = startTimeInfo.time;
3032
+ const awaitEndTime = endTimeInfo.time;
3033
+ logComponentAwait(
3034
+ asyncInfo,
3035
+ trackIdx,
3036
+ awaitStartTime,
3037
+ awaitEndTime,
3038
+ response._rootEnvironmentName,
3039
+ );
3040
+ }
3041
}
3042
}
3043
}
packages/react-client/src/ReactFlightPerformanceTrack.js
+47
-1
@@ -9,7 +9,11 @@
9
10
/* eslint-disable react-internal/no-production-logging */
11
12
-import type {ReactComponentInfo, ReactIOInfo} from 'shared/ReactTypes';
12
+import type {
13
+ ReactComponentInfo,
14
+ ReactIOInfo,
15
+ ReactAsyncInfo,
16
+} from 'shared/ReactTypes';
17
18
import {enableProfilerTimer} from 'shared/ReactFeatureFlags';
19
@@ -224,6 +228,48 @@ function getIOColor(
228
}
229
}
230
231
+export function logComponentAwait(
232
+ asyncInfo: ReactAsyncInfo,
233
+ trackIdx: number,
234
+ startTime: number,
235
+ endTime: number,
236
+ rootEnv: string,
237
+): void {
238
+ if (supportsUserTiming && endTime > 0) {
239
+ const env = asyncInfo.env;
240
+ const name = asyncInfo.awaited.name;
241
+ const isPrimaryEnv = env === rootEnv;
242
+ const color = getIOColor(name);
243
+ const entryName =
244
+ 'await ' +
245
+ (isPrimaryEnv || env === undefined ? name : name + ' [' + env + ']');
246
+ const debugTask = asyncInfo.debugTask;
247
+ if (__DEV__ && debugTask) {
248
+ debugTask.run(
249
+ // $FlowFixMe[method-unbinding]
250
+ console.timeStamp.bind(
251
+ console,
252
+ entryName,
253
+ startTime < 0 ? 0 : startTime,
254
+ endTime,
255
+ trackNames[trackIdx],
256
+ COMPONENTS_TRACK,
257
+ color,
258
+ ),
259
+ );
260
+ } else {
261
+ console.timeStamp(
262
+ entryName,
263
+ startTime < 0 ? 0 : startTime,
264
+ endTime,
265
+ trackNames[trackIdx],
266
+ COMPONENTS_TRACK,
267
+ color,
268
+ );
269
+ }
270
+ }
271
+}
272
+
273
export function logIOInfo(ioInfo: ReactIOInfo, rootEnv: string): void {
274
const startTime = ioInfo.start;
275
const endTime = ioInfo.end;
packages/react-server/src/ReactFlightAsyncSequence.js
+2
-2
@@ -37,8 +37,8 @@ export type AwaitNode = {
37
tag: 2,
38
owner: null | ReactComponentInfo,
39
stack: Error, // callsite that awaited (using await, .then(), Promise.all(), ...)
40
- start: -1.1, // not used. We use the timing of the awaited promise.
41
- end: -1.1, // not used.
40
+ start: number, // when we started blocking. This might be later than the I/O started.
41
+ end: number, // when we unblocked. This might be later than the I/O resolved if there's CPU time.
42
awaited: null | AsyncSequence, // the promise we were waiting on
43
previous: null | AsyncSequence, // the sequence that was blocking us from awaiting in the first place
44
};
packages/react-server/src/ReactFlightServer.js
+32
@@ -1919,6 +1919,24 @@ function visitAsyncNode(
1919
if (awaited !== null) {
1920
const ioNode = visitAsyncNode(request, task, awaited, cutOff, visited);
1921
if (ioNode !== null) {
1922
+ if (node.end < 0) {
1923
+ // If we haven't defined an end time, use the resolve of the inner Promise.
1924
+ // This can happen because the ping gets invoked before the await gets resolved.
1925
+ if (ioNode.end < node.start) {
1926
+ // If we're awaiting a resolved Promise it could have finished before we started.
1927
+ node.end = node.start;
1928
+ } else {
1929
+ node.end = ioNode.end;
1930
+ }
1931
+ }
1932
+ if (node.end < cutOff) {
1933
+ // This was already resolved when we started this sequence. It must have been
1934
+ // part of a different component.
1935
+ // TODO: Think of some other way to exclude irrelevant data since if we awaited
1936
+ // a cached promise, we should still log this component as being dependent on that data.
1937
+ return null;
1938
+ }
1939
+
1940
const stack = filterStackTrace(
1941
request,
1942
parseStackTrace(node.stack, 1),
@@ -1933,6 +1951,15 @@ function visitAsyncNode(
1951
// We log the environment at the time when the last promise pigned ping which may
1952
// be later than what the environment was when we actually started awaiting.
1953
const env = (0, request.environmentName)();
1954
+ if (node.start <= cutOff) {
1955
+ // If this was an await that started before this sequence but finished after,
1956
+ // then we clamp it to the start of this sequence. We don't need to emit a time
1957
+ // TODO: Typically we'll already have a previous time stamp with the cutOff time
1958
+ // so we shouldn't need to emit another one. But not always.
1959
+ emitTimingChunk(request, task.id, cutOff);
1960
+ } else {
1961
+ emitTimingChunk(request, task.id, node.start);
1962
+ }
1963
// Then emit a reference to us awaiting it in the current task.
1964
request.pendingChunks++;
1965
emitDebugChunk(request, task.id, {
@@ -1941,6 +1968,7 @@ function visitAsyncNode(
1968
owner: node.owner,
1969
stack: stack,
1970
});
1971
+ emitTimingChunk(request, task.id, node.end);
1972
}
1973
}
1974
// If we had awaited anything we would have written it now.
@@ -1976,10 +2004,14 @@ function emitAsyncSequence(
2004
// We log the environment at the time when we ping which may be later than what the
2005
// environment was when we actually started awaiting.
2006
const env = (0, request.environmentName)();
2007
+ // If we don't have any thing awaited, the time we started awaiting was internal
2008
+ // when we yielded after rendering. The cutOff time is basically that.
2009
+ emitTimingChunk(request, task.id, cutOff);
2010
emitDebugChunk(request, task.id, {
2011
awaited: ((awaitedNode: any): ReactIOInfo), // This is deduped by this reference.
2012
env: env,
2013
});
2014
+ emitTimingChunk(request, task.id, awaitedNode.end);
2015
}
2016
}
2017
packages/react-server/src/ReactFlightServerConfigDebugNode.js
+4
-6
@@ -49,8 +49,8 @@ export function initAsyncDebugInfo(): void {
49
tag: AWAIT_NODE,
50
owner: resolveOwner(),
51
stack: new Error(),
52
- start: -1.1,
53
- end: -1.1,
52
+ start: performance.now(),
53
+ end: -1.1, // set when resolved.
54
awaited: trigger, // The thing we're awaiting on. Might get overrriden when we resolve.
55
previous: current === undefined ? null : current, // The path that led us here.
56
}: AwaitNode);
@@ -118,10 +118,8 @@ export function initAsyncDebugInfo(): void {
118
'A Promise should never be an IO_NODE. This is a bug in React.',
119
);
120
}
121
- if (resolvedNode.tag === PROMISE_NODE) {
122
- // Log the end time when we resolved the promise.
123
- resolvedNode.end = performance.now();
124
- }
121
+ // Log the end time when we resolved the promise.
122
+ resolvedNode.end = performance.now();
123
const currentAsyncId = executionAsyncId();
124
if (asyncId !== currentAsyncId) {
125
// If the promise was not resolved by itself, then that means that
packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js
+24
-6
@@ -170,6 +170,9 @@ describe('ReactFlightAsyncDebugInfo', () => {
170
],
171
],
172
},
173
+ {
174
+ "time": 0,
175
+ },
176
{
177
"awaited": {
178
"end": 0,
@@ -257,6 +260,12 @@ describe('ReactFlightAsyncDebugInfo', () => {
260
],
261
],
262
},
263
+ {
264
+ "time": 0,
265
+ },
266
+ {
267
+ "time": 0,
268
+ },
269
{
270
"awaited": {
271
"end": 0,
@@ -347,6 +356,9 @@ describe('ReactFlightAsyncDebugInfo', () => {
356
{
357
"time": 0,
358
},
359
+ {
360
+ "time": 0,
361
+ },
362
]
363
`);
364
}
@@ -398,13 +410,16 @@ describe('ReactFlightAsyncDebugInfo', () => {
410
[
411
"Object.<anonymous>",
412
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
401
- 368,
413
+ 380,
414
109,
403
- 355,
415
+ 367,
416
67,
417
],
418
],
419
},
420
+ {
421
+ "time": 0,
422
+ },
423
{
424
"awaited": {
425
"end": 0,
@@ -420,9 +435,9 @@ describe('ReactFlightAsyncDebugInfo', () => {
435
[
436
"Object.<anonymous>",
437
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
423
- 368,
438
+ 380,
439
109,
425
- 355,
440
+ 367,
441
67,
442
],
443
],
@@ -431,9 +446,9 @@ describe('ReactFlightAsyncDebugInfo', () => {
446
[
447
"Component",
448
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
434
- 358,
449
+ 370,
450
7,
436
- 356,
451
+ 368,
452
5,
453
],
454
],
@@ -444,6 +459,9 @@ describe('ReactFlightAsyncDebugInfo', () => {
459
{
460
"time": 0,
461
},
462
+ {
463
+ "time": 0,
464
+ },
465
]
466
`);
467
}