Log yielded time in the Component Track (#31563)

sebmarkbage · web-flow · commit 7c254b65761c · 2024-11-19T13:56:22.000-05:00
Stacked on #31552. Must be tested with `enableSiblingPrerendering` off since the `use()` optimization is not on there yet. This adds a span to the Components track when we yield in the middle of the event loop. In this scenario, the "Render" span continues through out the Scheduler track. So you can see that the Component itself might not take a long time but yielding inside of it might. This lets you see if something was blocking the React render loop while yielding. If we're blocked 1ms or longer we log that as "Blocked". If we're yielding due to suspending in the middle of the work loop we log this as "Suspended". <img width="837" alt="Screenshot 2024-11-16 at 1 15 14 PM" src="https://github.com/user-attachments/assets/45a858ea-17e6-416c-af1a-78c126e033f3"> If the render doesn't commit because it restarts due to some other prewarming or because some non-`use()` suspends, it doesn't have from context components. <img width="971" alt="Screenshot 2024-11-16 at 1 13 55 PM" src="https://github.com/user-attachments/assets/a67724f8-702e-4e7d-9499-9ffc09541a61"> The `useActionState` path doesn't work yet because the `use()` optimization doesn't work there for some reason. But the idea is that it should mark the time that the component is blocked as Action instead of Suspended.
diff --git a/packages/react-reconciler/src/ReactFiberPerformanceTrack.js b/packages/react-reconciler/src/ReactFiberPerformanceTrack.js
@@ -114,6 +114,54 @@ export function logComponentEffect(
   }
 }
 
+export function logYieldTime(startTime: number, endTime: number): void {
+  if (supportsUserTiming) {
+    const yieldDuration = endTime - startTime;
+    if (yieldDuration < 1) {
+      // Skip sub-millisecond yields. This happens all the time and is not interesting.
+      return;
+    }
+    // Being blocked on CPU is potentially bad so we color it by how long it took.
+    reusableComponentDevToolDetails.color =
+      yieldDuration < 5
+        ? 'primary-light'
+        : yieldDuration < 10
+          ? 'primary'
+          : yieldDuration < 100
+            ? 'primary-dark'
+            : 'error';
+    reusableComponentOptions.start = startTime;
+    reusableComponentOptions.end = endTime;
+    performance.measure('Blocked', reusableComponentOptions);
+  }
+}
+
+export function logSuspendedYieldTime(
+  startTime: number,
+  endTime: number,
+  suspendedFiber: Fiber,
+): void {
+  if (supportsUserTiming) {
+    reusableComponentDevToolDetails.color = 'primary-light';
+    reusableComponentOptions.start = startTime;
+    reusableComponentOptions.end = endTime;
+    performance.measure('Suspended', reusableComponentOptions);
+  }
+}
+
+export function logActionYieldTime(
+  startTime: number,
+  endTime: number,
+  suspendedFiber: Fiber,
+): void {
+  if (supportsUserTiming) {
+    reusableComponentDevToolDetails.color = 'primary-light';
+    reusableComponentOptions.start = startTime;
+    reusableComponentOptions.end = endTime;
+    performance.measure('Action', reusableComponentOptions);
+  }
+}
+
 export function logBlockingStart(
   updateTime: number,
   eventTime: number,
diff --git a/packages/react-reconciler/src/ReactFiberWorkLoop.js b/packages/react-reconciler/src/ReactFiberWorkLoop.js
@@ -79,6 +79,9 @@ import {
   logCommitPhase,
   logPaintYieldPhase,
   logPassiveCommitPhase,
+  logYieldTime,
+  logActionYieldTime,
+  logSuspendedYieldTime,
 } from './ReactFiberPerformanceTrack';
 
 import {
@@ -264,6 +267,9 @@ import {
   stopProfilerTimerIfRunningAndRecordIncompleteDuration,
   markUpdateAsRepeat,
   trackSuspendedTime,
+  startYieldTimer,
+  yieldStartTime,
+  yieldReason,
 } from './ReactProfilerTimer';
 import {setCurrentTrackFromLanes} from './ReactFiberPerformanceTrack';
 
@@ -351,7 +357,7 @@ let workInProgress: Fiber | null = null;
 // The lanes we're rendering
 let workInProgressRootRenderLanes: Lanes = NoLanes;
 
-opaque type SuspendedReason = 0 | 1 | 2 | 3 | 4 | 5 | 6 | 7 | 8 | 9;
+export opaque type SuspendedReason = 0 | 1 | 2 | 3 | 4 | 5 | 6 | 7 | 8 | 9;
 const NotSuspended: SuspendedReason = 0;
 const SuspendedOnError: SuspendedReason = 1;
 const SuspendedOnData: SuspendedReason = 2;
@@ -915,6 +921,24 @@ export function performWorkOnRoot(
     throw new Error('Should not already be working.');
   }
 
+  if (enableProfilerTimer && enableComponentPerformanceTrack) {
+    if (workInProgressRootRenderLanes !== NoLanes && workInProgress !== null) {
+      const yieldedFiber = workInProgress;
+      // We've returned from yielding to the event loop. Let's log the time it took.
+      const yieldEndTime = now();
+      switch (yieldReason) {
+        case SuspendedOnData:
+          logSuspendedYieldTime(yieldStartTime, yieldEndTime, yieldedFiber);
+          break;
+        case SuspendedOnAction:
+          logActionYieldTime(yieldStartTime, yieldEndTime, yieldedFiber);
+          break;
+        default:
+          logYieldTime(yieldStartTime, yieldEndTime);
+      }
+    }
+  }
+
   // We disable time-slicing in some cases: if the work has been CPU-bound
   // for too long ("expired" work, to prevent starvation), or we're in
   // sync-updates-by-default mode.
@@ -956,6 +980,12 @@ export function performWorkOnRoot(
         const didAttemptEntireTree = false;
         markRootSuspended(root, lanes, NoLane, didAttemptEntireTree);
       }
+      if (enableProfilerTimer && enableComponentPerformanceTrack) {
+        // We're about to yield. Let's keep track of how long we yield to the event loop.
+        // We also stash the suspended reason at the time we yielded since it might have
+        // changed when we resume such as when it gets pinged.
+        startYieldTimer(workInProgressSuspendedReason);
+      }
       break;
     } else {
       let renderEndTime = 0;
diff --git a/packages/react-reconciler/src/ReactProfilerTimer.js b/packages/react-reconciler/src/ReactProfilerTimer.js
@@ -9,6 +9,8 @@
 
 import type {Fiber} from './ReactInternalTypes';
 
+import type {SuspendedReason} from './ReactFiberWorkLoop';
+
 import type {Lane, Lanes} from './ReactFiberLane';
 import {
   isTransitionLane,
@@ -58,6 +60,17 @@ export let transitionEventType: null | string = null; // Event type of the first
 export let transitionEventIsRepeat: boolean = false;
 export let transitionSuspendedTime: number = -1.1;
 
+export let yieldReason: SuspendedReason = (0: any);
+export let yieldStartTime: number = -1.1; // The time when we yielded to the event loop
+
+export function startYieldTimer(reason: SuspendedReason) {
+  if (!enableProfilerTimer || !enableComponentPerformanceTrack) {
+    return;
+  }
+  yieldStartTime = now();
+  yieldReason = reason;
+}
+
 export function startUpdateTimerByLane(lane: Lane): void {
   if (!enableProfilerTimer || !enableComponentPerformanceTrack) {
     return;
