Track suspended time when the render doesn't commit because it suspended (#31552)

sebmarkbage · web-flow · commit 6177b18c66c0 · 2024-11-19T13:42:44.000-05:00
When we suspend the render with delay, we won't do any more work until we get some kind of another update/ping. It's because conceptually something is suspended and then will update later. We need to highlight this period to show why it's not doing any work. We fill the empty space with "Suspended". This stops whenever the same lane group starts rendering again. Clamped by the preceeding start time/event time/update time. <img width="902" alt="Screenshot 2024-11-15 at 1 01 29 PM" src="https://github.com/user-attachments/assets/acf9dc9a-8fc3-4367-a8b0-d19f9c9eac73"> Ideally we would instead start the next render and suspend the work loop at all places we suspend. In that mode this will instead show up as a very long "Render" with a "Suspended" period instead highlighted in the Components track as one component is suspended. We'll soon have that for `use()` but not all updates so this covers the rest. One issue with `useActionState` is that it is implemented as suspending at the point of the `useActionState` which means that the period of the Action shows up as a suspended render instead of as an Action which happens for raw actions. This is not really how you conceptually think about it so we need some special case for `useActionState`. In the screenshot above, the first "Suspended" is actually awaiting an Action and the second "Suspended" is awaiting the data from it.
diff --git a/packages/react-reconciler/src/ReactFiberPerformanceTrack.js b/packages/react-reconciler/src/ReactFiberPerformanceTrack.js
@@ -222,6 +222,19 @@ export function logSuspendedRenderPhase(
   }
 }
 
+export function logSuspendedWithDelayPhase(
+  startTime: number,
+  endTime: number,
+): void {
+  // This means the render was suspended and cannot commit until it gets unblocked.
+  if (supportsUserTiming) {
+    reusableLaneDevToolDetails.color = 'primary-dark';
+    reusableLaneOptions.start = startTime;
+    reusableLaneOptions.end = endTime;
+    performance.measure('Suspended', reusableLaneOptions);
+  }
+}
+
 export function logErroredRenderPhase(
   startTime: number,
   endTime: number,
diff --git a/packages/react-reconciler/src/ReactFiberWorkLoop.js b/packages/react-reconciler/src/ReactFiberWorkLoop.js
@@ -73,6 +73,7 @@ import {
   logSuspendedRenderPhase,
   logErroredRenderPhase,
   logInconsistentRender,
+  logSuspendedWithDelayPhase,
   logSuspenseThrottlePhase,
   logSuspendedCommitPhase,
   logCommitPhase,
@@ -239,12 +240,14 @@ import {
   blockingEventTime,
   blockingEventType,
   blockingEventIsRepeat,
+  blockingSuspendedTime,
   transitionClampTime,
   transitionStartTime,
   transitionUpdateTime,
   transitionEventTime,
   transitionEventType,
   transitionEventIsRepeat,
+  transitionSuspendedTime,
   clearBlockingTimers,
   clearTransitionTimers,
   clampBlockingTimers,
@@ -260,6 +263,7 @@ import {
   stopProfilerTimerIfRunningAndRecordDuration,
   stopProfilerTimerIfRunningAndRecordIncompleteDuration,
   markUpdateAsRepeat,
+  trackSuspendedTime,
 } from './ReactProfilerTimer';
 import {setCurrentTrackFromLanes} from './ReactFiberPerformanceTrack';
 
@@ -954,6 +958,11 @@ export function performWorkOnRoot(
       }
       break;
     } else {
+      let renderEndTime = 0;
+      if (enableProfilerTimer && enableComponentPerformanceTrack) {
+        renderEndTime = now();
+      }
+
       // The render completed.
 
       // Check if this render may have yielded to a concurrent event, and if so,
@@ -968,7 +977,6 @@ export function performWorkOnRoot(
       ) {
         if (enableProfilerTimer && enableComponentPerformanceTrack) {
           setCurrentTrackFromLanes(lanes);
-          const renderEndTime = now();
           logInconsistentRender(renderStartTime, renderEndTime);
           finalizeRender(lanes, renderEndTime);
           markUpdateAsRepeat(lanes);
@@ -996,7 +1004,6 @@ export function performWorkOnRoot(
         if (errorRetryLanes !== NoLanes) {
           if (enableProfilerTimer && enableComponentPerformanceTrack) {
             setCurrentTrackFromLanes(lanes);
-            const renderEndTime = now();
             logErroredRenderPhase(renderStartTime, renderEndTime);
             finalizeRender(lanes, renderEndTime);
             markUpdateAsRepeat(lanes);
@@ -1020,13 +1027,15 @@ export function performWorkOnRoot(
             continue;
           } else {
             // The root errored yet again. Proceed to commit the tree.
+            if (enableProfilerTimer && enableComponentPerformanceTrack) {
+              renderEndTime = now();
+            }
           }
         }
       }
       if (exitStatus === RootFatalErrored) {
         if (enableProfilerTimer && enableComponentPerformanceTrack) {
           setCurrentTrackFromLanes(lanes);
-          const renderEndTime = now();
           logErroredRenderPhase(renderStartTime, renderEndTime);
           finalizeRender(lanes, renderEndTime);
         }
@@ -1040,7 +1049,13 @@ export function performWorkOnRoot(
 
       // We now have a consistent tree. The next step is either to commit it,
       // or, if something suspended, wait to commit it after a timeout.
-      finishConcurrentRender(root, exitStatus, finishedWork, lanes);
+      finishConcurrentRender(
+        root,
+        exitStatus,
+        finishedWork,
+        lanes,
+        renderEndTime,
+      );
     }
     break;
   } while (true);
@@ -1139,14 +1154,8 @@ function finishConcurrentRender(
   exitStatus: RootExitStatus,
   finishedWork: Fiber,
   lanes: Lanes,
+  renderEndTime: number, // Profiling-only
 ) {
-  let renderEndTime = 0;
-  if (enableProfilerTimer && enableComponentPerformanceTrack) {
-    // Track when we finished the last unit of work, before we actually commit it.
-    // The commit can be suspended/blocked until we commit it.
-    renderEndTime = now();
-  }
-
   // TODO: The fact that most of these branches are identical suggests that some
   // of the exit statuses are not best modeled as exit statuses and should be
   // tracked orthogonally.
@@ -1170,6 +1179,7 @@ function finishConcurrentRender(
         setCurrentTrackFromLanes(lanes);
         logSuspendedRenderPhase(renderStartTime, renderEndTime);
         finalizeRender(lanes, renderEndTime);
+        trackSuspendedTime(lanes, renderEndTime);
       }
       const didAttemptEntireTree = !workInProgressRootDidSkipSuspendedSiblings;
       markRootSuspended(
@@ -1705,30 +1715,64 @@ function prepareFreshStack(root: FiberRoot, lanes: Lanes): Fiber {
     }
 
     if (includesSyncLane(lanes) || includesBlockingLane(lanes)) {
-      logBlockingStart(
+      const clampedUpdateTime =
         blockingUpdateTime >= 0 && blockingUpdateTime < blockingClampTime
           ? blockingClampTime
-          : blockingUpdateTime,
+          : blockingUpdateTime;
+      const clampedEventTime =
         blockingEventTime >= 0 && blockingEventTime < blockingClampTime
           ? blockingClampTime
-          : blockingEventTime,
+          : blockingEventTime;
+      if (blockingSuspendedTime >= 0) {
+        setCurrentTrackFromLanes(lanes);
+        logSuspendedWithDelayPhase(
+          blockingSuspendedTime,
+          // Clamp the suspended time to the first event/update.
+          clampedEventTime >= 0
+            ? clampedEventTime
+            : clampedUpdateTime >= 0
+              ? clampedUpdateTime
+              : renderStartTime,
+        );
+      }
+      logBlockingStart(
+        clampedUpdateTime,
+        clampedEventTime,
         blockingEventType,
         blockingEventIsRepeat,
         renderStartTime,
       );
       clearBlockingTimers();
     }
     if (includesTransitionLane(lanes)) {
-      logTransitionStart(
+      const clampedStartTime =
         transitionStartTime >= 0 && transitionStartTime < transitionClampTime
           ? transitionClampTime
-          : transitionStartTime,
+          : transitionStartTime;
+      const clampedUpdateTime =
         transitionUpdateTime >= 0 && transitionUpdateTime < transitionClampTime
           ? transitionClampTime
-          : transitionUpdateTime,
+          : transitionUpdateTime;
+      const clampedEventTime =
         transitionEventTime >= 0 && transitionEventTime < transitionClampTime
           ? transitionClampTime
-          : transitionEventTime,
+          : transitionEventTime;
+      if (transitionSuspendedTime >= 0) {
+        setCurrentTrackFromLanes(lanes);
+        logSuspendedWithDelayPhase(
+          transitionSuspendedTime,
+          // Clamp the suspended time to the first event/update.
+          clampedEventTime >= 0
+            ? clampedEventTime
+            : clampedUpdateTime >= 0
+              ? clampedUpdateTime
+              : renderStartTime,
+        );
+      }
+      logTransitionStart(
+        clampedStartTime,
+        clampedUpdateTime,
+        clampedEventTime,
         transitionEventType,
         transitionEventIsRepeat,
         renderStartTime,
diff --git a/packages/react-reconciler/src/ReactProfilerTimer.js b/packages/react-reconciler/src/ReactProfilerTimer.js
@@ -48,13 +48,15 @@ export let blockingUpdateTime: number = -1.1; // First sync setState scheduled.
 export let blockingEventTime: number = -1.1; // Event timeStamp of the first setState.
 export let blockingEventType: null | string = null; // Event type of the first setState.
 export let blockingEventIsRepeat: boolean = false;
+export let blockingSuspendedTime: number = -1.1;
 // TODO: This should really be one per Transition lane.
 export let transitionClampTime: number = -0;
 export let transitionStartTime: number = -1.1; // First startTransition call before setState.
 export let transitionUpdateTime: number = -1.1; // First transition setState scheduled.
 export let transitionEventTime: number = -1.1; // Event timeStamp of the first transition.
 export let transitionEventType: null | string = null; // Event type of the first transition.
 export let transitionEventIsRepeat: boolean = false;
+export let transitionSuspendedTime: number = -1.1;
 
 export function startUpdateTimerByLane(lane: Lane): void {
   if (!enableProfilerTimer || !enableComponentPerformanceTrack) {
@@ -100,8 +102,20 @@ export function markUpdateAsRepeat(lanes: Lanes): void {
   }
 }
 
+export function trackSuspendedTime(lanes: Lanes, renderEndTime: number) {
+  if (!enableProfilerTimer || !enableComponentPerformanceTrack) {
+    return;
+  }
+  if (includesSyncLane(lanes) || includesBlockingLane(lanes)) {
+    blockingSuspendedTime = renderEndTime;
+  } else if (includesTransitionLane(lanes)) {
+    transitionSuspendedTime = renderEndTime;
+  }
+}
+
 export function clearBlockingTimers(): void {
   blockingUpdateTime = -1.1;
+  blockingSuspendedTime = -1.1;
 }
 
 export function startAsyncTransitionTimer(): void {
@@ -145,6 +159,7 @@ export function clearAsyncTransitionTimer(): void {
 export function clearTransitionTimers(): void {
   transitionStartTime = -1.1;
   transitionUpdateTime = -1.1;
+  transitionSuspendedTime = -1.1;
 }
 
 export function clampBlockingTimers(finalTime: number): void {
