[Flight] Log aborted await and component renders

packages/react-client/src/ReactFlightClient.js

@@ -77,10 +77,12 @@ import {
   markAllTracksInOrder,
   logComponentRender,
   logDedupedComponentRender,
+  logComponentAborted,
   logComponentErrored,
   logIOInfo,
   logIOInfoErrored,
   logComponentAwait,
+  logComponentAwaitAborted,
   logComponentAwaitErrored,
 } from './ReactFlightPerformanceTrack';
 
@@ -1812,6 +1814,12 @@ function ResponseInstance(
     this._replayConsole = replayConsole;
     this._rootEnvironmentName = rootEnv;
   }
+  if (enableProfilerTimer && enableComponentPerformanceTrack) {
+    // Since we don't know when recording of profiles will start and stop, we have to
+    // mark the order over and over again.
+    markAllTracksInOrder();
+  }
+
   // Don't inline this call because it causes closure to outline the call above.
   this._fromJSON = createFromJSONCallback(this);
 }
@@ -3291,6 +3299,44 @@ function flushComponentPerformance(
             }
           }
         }
+      } else {
+        // Anything between the end and now was aborted if it has no end time.
+        // Either because the client stream was aborted reading it or the server stream aborted.
+        endTime = time; // If we don't find anything else the endTime is the start time.
+        for (let j = debugInfo.length - 1; j > i; j--) {
+          const candidateInfo = debugInfo[j];
+          if (typeof candidateInfo.name === 'string') {
+            if (componentEndTime > childrenEndTime) {
+              childrenEndTime = componentEndTime;
+            }
+            // $FlowFixMe: Refined.
+            const componentInfo: ReactComponentInfo = candidateInfo;
+            const env = response._rootEnvironmentName;
+            logComponentAborted(
+              componentInfo,
+              trackIdx,
+              time,
+              componentEndTime,
+              childrenEndTime,
+              env,
+            );
+            componentEndTime = time; // The end time of previous component is the start time of the next.
+            // Track the root most component of the result for deduping logging.
+            result.component = componentInfo;
+            isLastComponent = false;
+          } else if (candidateInfo.awaited) {
+            // If we don't have an end time for an await, that means we aborted.
+            const asyncInfo: ReactAsyncInfo = candidateInfo;
+            const env = response._rootEnvironmentName;
+            if (asyncInfo.awaited.end > endTime) {
+              endTime = asyncInfo.awaited.end; // Take the end time of the I/O as the await end.
+            }
+            if (endTime > childrenEndTime) {
+              childrenEndTime = endTime;
+            }
+            logComponentAwaitAborted(asyncInfo, trackIdx, time, endTime, env);
+          }
+        }
       }
       endTime = time; // The end time of the next entry is this time.
       endTimeIdx = i;

packages/react-client/src/ReactFlightPerformanceTrack.js

@@ -247,6 +247,53 @@ export function logComponentRender(
   }
 }
 
+export function logComponentAborted(
+  componentInfo: ReactComponentInfo,
+  trackIdx: number,
+  startTime: number,
+  endTime: number,
+  childrenEndTime: number,
+  rootEnv: string,
+): void {
+  if (supportsUserTiming) {
+    const env = componentInfo.env;
+    const name = componentInfo.name;
+    const isPrimaryEnv = env === rootEnv;
+    const entryName =
+      isPrimaryEnv || env === undefined ? name : name + ' [' + env + ']';
+    if (__DEV__) {
+      const properties = [
+        [
+          'Aborted',
+          'The stream was aborted before this Component finished rendering.',
+        ],
+      ];
+      performance.measure(entryName, {
+        start: startTime < 0 ? 0 : startTime,
+        end: childrenEndTime,
+        detail: {
+          devtools: {
+            color: 'warning',
+            track: trackNames[trackIdx],
+            trackGroup: COMPONENTS_TRACK,
+            tooltipText: entryName + ' Aborted',
+            properties,
+          },
+        },
+      });
+    } else {
+      console.timeStamp(
+        entryName,
+        startTime < 0 ? 0 : startTime,
+        childrenEndTime,
+        trackNames[trackIdx],
+        COMPONENTS_TRACK,
+        'warning',
+      );
+    }
+  }
+}
+
 export function logComponentErrored(
   componentInfo: ReactComponentInfo,
   trackIdx: number,
@@ -352,6 +399,54 @@ function getIOColor(
   }
 }
 
+export function logComponentAwaitAborted(
+  asyncInfo: ReactAsyncInfo,
+  trackIdx: number,
+  startTime: number,
+  endTime: number,
+  rootEnv: string,
+): void {
+  if (supportsUserTiming && endTime > 0) {
+    const env = asyncInfo.env;
+    const name = asyncInfo.awaited.name;
+    const isPrimaryEnv = env === rootEnv;
+    const entryName =
+      'await ' +
+      (isPrimaryEnv || env === undefined ? name : name + ' [' + env + ']');
+    const debugTask = asyncInfo.debugTask || asyncInfo.awaited.debugTask;
+    if (__DEV__ && debugTask) {
+      const properties = [
+        ['Aborted', 'The stream was aborted before this Promise resolved.'],
+      ];
+      debugTask.run(
+        // $FlowFixMe[method-unbinding]
+        performance.measure.bind(performance, entryName, {
+          start: startTime < 0 ? 0 : startTime,
+          end: endTime,
+          detail: {
+            devtools: {
+              color: 'warning',
+              track: trackNames[trackIdx],
+              trackGroup: COMPONENTS_TRACK,
+              properties,
+              tooltipText: entryName + ' Aborted',
+            },
+          },
+        }),
+      );
+    } else {
+      console.timeStamp(
+        entryName,
+        startTime < 0 ? 0 : startTime,
+        endTime,
+        trackNames[trackIdx],
+        COMPONENTS_TRACK,
+        'warning',
+      );
+    }
+  }
+}
+
 export function logComponentAwaitErrored(
   asyncInfo: ReactAsyncInfo,
   trackIdx: number,
@@ -367,7 +462,7 @@ export function logComponentAwaitErrored(
     const entryName =
       'await ' +
       (isPrimaryEnv || env === undefined ? name : name + ' [' + env + ']');
-    const debugTask = asyncInfo.debugTask;
+    const debugTask = asyncInfo.debugTask || asyncInfo.awaited.debugTask;
     if (__DEV__ && debugTask) {
       const message =
         typeof error === 'object' &&
@@ -423,7 +518,7 @@ export function logComponentAwait(
     const entryName =
       'await ' +
       (isPrimaryEnv || env === undefined ? name : name + ' [' + env + ']');
-    const debugTask = asyncInfo.debugTask;
+    const debugTask = asyncInfo.debugTask || asyncInfo.awaited.debugTask;
     if (__DEV__ && debugTask) {
       const properties: Array<[string, string]> = [];
       if (typeof value === 'object' && value !== null) {

packages/react-server/src/ReactFlightServer.js

@@ -2151,9 +2151,7 @@ function visitAsyncNode(
               });
               // Mark the end time of the await. If we're aborting then we don't emit this
               // to signal that this never resolved inside this render.
-              if (request.status !== ABORTING) {
-                markOperationEndTime(request, task, endTime);
-              }
+              markOperationEndTime(request, task, endTime);
             }
           }
         }
@@ -2216,10 +2214,8 @@ function emitAsyncSequence(
     emitDebugChunk(request, task.id, debugInfo);
     // Mark the end time of the await. If we're aborting then we don't emit this
     // to signal that this never resolved inside this render.
-    if (request.status !== ABORTING) {
-      // If we're currently aborting, then this never resolved into user space.
-      markOperationEndTime(request, task, awaitedNode.end);
-    }
+    // If we're currently aborting, then this never resolved into user space.
+    markOperationEndTime(request, task, awaitedNode.end);
   }
 }
 
@@ -4808,6 +4804,10 @@ function markOperationEndTime(request: Request, task: Task, timestamp: number) {
   }
   // This is like advanceTaskTime() but always emits a timing chunk even if it doesn't advance.
   // This ensures that the end time of the previous entry isn't implied to be the start of the next one.
+  if (request.status === ABORTING) {
+    // If we're aborting then we don't emit any end times that happened after.
+    return;
+  }
   if (timestamp > task.time) {
     emitTimingChunk(request, task.id, timestamp);
     task.time = timestamp;