Log yielded time in the Component Track

Author: sebmarkbage

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,

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;

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;