[Flight] Log aborted await and component renders (#33641)
<img width="926" alt="Screenshot 2025-06-25 at 1 02 14 PM" src="https://github.com/user-attachments/assets/1877d13d-5259-4cc4-8f48-12981e3073fe" /> The I/O entry doesn't show as aborted in the Server Request track because technically it wasn't. The end time is just made up. It's still going. It's not aborted until the abort signal propagates and if we do get that signal wired up before it emits, it instead would show up as rejected. --------- Co-authored-by: Hendrik Liebau <mail@hendrik-liebau.de>
Sebastian Markbåge committed
Jun 25, 2025 at 16:28 UTC
bb6c9d521e7f44eb9a9754a14cde62c8e6439e5e
3 files changed
+150
-9
packages/react-client/src/ReactFlightClient.js
+46
@@ -77,10 +77,12 @@ import {
77
markAllTracksInOrder,
78
logComponentRender,
79
logDedupedComponentRender,
80
+ logComponentAborted,
81
logComponentErrored,
82
logIOInfo,
83
logIOInfoErrored,
84
logComponentAwait,
85
+ logComponentAwaitAborted,
86
logComponentAwaitErrored,
87
} from './ReactFlightPerformanceTrack';
88
@@ -1812,6 +1814,12 @@ function ResponseInstance(
1814
this._replayConsole = replayConsole;
1815
this._rootEnvironmentName = rootEnv;
1816
}
1817
+ if (enableProfilerTimer && enableComponentPerformanceTrack) {
1818
+ // Since we don't know when recording of profiles will start and stop, we have to
1819
+ // mark the order over and over again.
1820
+ markAllTracksInOrder();
1821
+ }
1822
+
1823
// Don't inline this call because it causes closure to outline the call above.
1824
this._fromJSON = createFromJSONCallback(this);
1825
}
@@ -3291,6 +3299,44 @@ function flushComponentPerformance(
3299
}
3300
}
3301
}
3302
+ } else {
3303
+ // Anything between the end and now was aborted if it has no end time.
3304
+ // Either because the client stream was aborted reading it or the server stream aborted.
3305
+ endTime = time; // If we don't find anything else the endTime is the start time.
3306
+ for (let j = debugInfo.length - 1; j > i; j--) {
3307
+ const candidateInfo = debugInfo[j];
3308
+ if (typeof candidateInfo.name === 'string') {
3309
+ if (componentEndTime > childrenEndTime) {
3310
+ childrenEndTime = componentEndTime;
3311
+ }
3312
+ // $FlowFixMe: Refined.
3313
+ const componentInfo: ReactComponentInfo = candidateInfo;
3314
+ const env = response._rootEnvironmentName;
3315
+ logComponentAborted(
3316
+ componentInfo,
3317
+ trackIdx,
3318
+ time,
3319
+ componentEndTime,
3320
+ childrenEndTime,
3321
+ env,
3322
+ );
3323
+ componentEndTime = time; // The end time of previous component is the start time of the next.
3324
+ // Track the root most component of the result for deduping logging.
3325
+ result.component = componentInfo;
3326
+ isLastComponent = false;
3327
+ } else if (candidateInfo.awaited) {
3328
+ // If we don't have an end time for an await, that means we aborted.
3329
+ const asyncInfo: ReactAsyncInfo = candidateInfo;
3330
+ const env = response._rootEnvironmentName;
3331
+ if (asyncInfo.awaited.end > endTime) {
3332
+ endTime = asyncInfo.awaited.end; // Take the end time of the I/O as the await end.
3333
+ }
3334
+ if (endTime > childrenEndTime) {
3335
+ childrenEndTime = endTime;
3336
+ }
3337
+ logComponentAwaitAborted(asyncInfo, trackIdx, time, endTime, env);
3338
+ }
3339
+ }
3340
}
3341
endTime = time; // The end time of the next entry is this time.
3342
endTimeIdx = i;
packages/react-client/src/ReactFlightPerformanceTrack.js
+97
-2
@@ -247,6 +247,53 @@ export function logComponentRender(
247
}
248
}
249
250
+export function logComponentAborted(
251
+ componentInfo: ReactComponentInfo,
252
+ trackIdx: number,
253
+ startTime: number,
254
+ endTime: number,
255
+ childrenEndTime: number,
256
+ rootEnv: string,
257
+): void {
258
+ if (supportsUserTiming) {
259
+ const env = componentInfo.env;
260
+ const name = componentInfo.name;
261
+ const isPrimaryEnv = env === rootEnv;
262
+ const entryName =
263
+ isPrimaryEnv || env === undefined ? name : name + ' [' + env + ']';
264
+ if (__DEV__) {
265
+ const properties = [
266
+ [
267
+ 'Aborted',
268
+ 'The stream was aborted before this Component finished rendering.',
269
+ ],
270
+ ];
271
+ performance.measure(entryName, {
272
+ start: startTime < 0 ? 0 : startTime,
273
+ end: childrenEndTime,
274
+ detail: {
275
+ devtools: {
276
+ color: 'warning',
277
+ track: trackNames[trackIdx],
278
+ trackGroup: COMPONENTS_TRACK,
279
+ tooltipText: entryName + ' Aborted',
280
+ properties,
281
+ },
282
+ },
283
+ });
284
+ } else {
285
+ console.timeStamp(
286
+ entryName,
287
+ startTime < 0 ? 0 : startTime,
288
+ childrenEndTime,
289
+ trackNames[trackIdx],
290
+ COMPONENTS_TRACK,
291
+ 'warning',
292
+ );
293
+ }
294
+ }
295
+}
296
+
297
export function logComponentErrored(
298
componentInfo: ReactComponentInfo,
299
trackIdx: number,
@@ -352,6 +399,54 @@ function getIOColor(
399
}
400
}
401
402
+export function logComponentAwaitAborted(
403
+ asyncInfo: ReactAsyncInfo,
404
+ trackIdx: number,
405
+ startTime: number,
406
+ endTime: number,
407
+ rootEnv: string,
408
+): void {
409
+ if (supportsUserTiming && endTime > 0) {
410
+ const env = asyncInfo.env;
411
+ const name = asyncInfo.awaited.name;
412
+ const isPrimaryEnv = env === rootEnv;
413
+ const entryName =
414
+ 'await ' +
415
+ (isPrimaryEnv || env === undefined ? name : name + ' [' + env + ']');
416
+ const debugTask = asyncInfo.debugTask || asyncInfo.awaited.debugTask;
417
+ if (__DEV__ && debugTask) {
418
+ const properties = [
419
+ ['Aborted', 'The stream was aborted before this Promise resolved.'],
420
+ ];
421
+ debugTask.run(
422
+ // $FlowFixMe[method-unbinding]
423
+ performance.measure.bind(performance, entryName, {
424
+ start: startTime < 0 ? 0 : startTime,
425
+ end: endTime,
426
+ detail: {
427
+ devtools: {
428
+ color: 'warning',
429
+ track: trackNames[trackIdx],
430
+ trackGroup: COMPONENTS_TRACK,
431
+ properties,
432
+ tooltipText: entryName + ' Aborted',
433
+ },
434
+ },
435
+ }),
436
+ );
437
+ } else {
438
+ console.timeStamp(
439
+ entryName,
440
+ startTime < 0 ? 0 : startTime,
441
+ endTime,
442
+ trackNames[trackIdx],
443
+ COMPONENTS_TRACK,
444
+ 'warning',
445
+ );
446
+ }
447
+ }
448
+}
449
+
450
export function logComponentAwaitErrored(
451
asyncInfo: ReactAsyncInfo,
452
trackIdx: number,
@@ -367,7 +462,7 @@ export function logComponentAwaitErrored(
462
const entryName =
463
'await ' +
464
(isPrimaryEnv || env === undefined ? name : name + ' [' + env + ']');
370
- const debugTask = asyncInfo.debugTask;
465
+ const debugTask = asyncInfo.debugTask || asyncInfo.awaited.debugTask;
466
if (__DEV__ && debugTask) {
467
const message =
468
typeof error === 'object' &&
@@ -423,7 +518,7 @@ export function logComponentAwait(
518
const entryName =
519
'await ' +
520
(isPrimaryEnv || env === undefined ? name : name + ' [' + env + ']');
426
- const debugTask = asyncInfo.debugTask;
521
+ const debugTask = asyncInfo.debugTask || asyncInfo.awaited.debugTask;
522
if (__DEV__ && debugTask) {
523
const properties: Array<[string, string]> = [];
524
if (typeof value === 'object' && value !== null) {
packages/react-server/src/ReactFlightServer.js
+7
-7
@@ -2151,9 +2151,7 @@ function visitAsyncNode(
2151
});
2152
// Mark the end time of the await. If we're aborting then we don't emit this
2153
// to signal that this never resolved inside this render.
2154
- if (request.status !== ABORTING) {
2155
- markOperationEndTime(request, task, endTime);
2156
- }
2154
+ markOperationEndTime(request, task, endTime);
2155
}
2156
}
2157
}
@@ -2216,10 +2214,8 @@ function emitAsyncSequence(
2214
emitDebugChunk(request, task.id, debugInfo);
2215
// Mark the end time of the await. If we're aborting then we don't emit this
2216
// to signal that this never resolved inside this render.
2219
- if (request.status !== ABORTING) {
2220
- // If we're currently aborting, then this never resolved into user space.
2221
- markOperationEndTime(request, task, awaitedNode.end);
2222
- }
2217
+ // If we're currently aborting, then this never resolved into user space.
2218
+ markOperationEndTime(request, task, awaitedNode.end);
2219
}
2220
}
2221
@@ -4808,6 +4804,10 @@ function markOperationEndTime(request: Request, task: Task, timestamp: number) {
4804
}
4805
// This is like advanceTaskTime() but always emits a timing chunk even if it doesn't advance.
4806
// This ensures that the end time of the previous entry isn't implied to be the start of the next one.
4807
+ if (request.status === ABORTING) {
4808
+ // If we're aborting then we don't emit any end times that happened after.
4809
+ return;
4810
+ }
4811
if (timestamp > task.time) {
4812
emitTimingChunk(request, task.id, timestamp);
4813
task.time = timestamp;