[Fiber] Log Component Effects to Performance Track (#30983)

Stacked on #30981. Same as #30967 but for effects.

This logs a tree of components using `performance.measure()`.

In addition to the previous render phase this logs one tree for each
commit phase:

- Mutation Phase
- Layout Effect
- Passive Unmounts
- Passive Mounts

I currently skip the Before Mutation phase since the snapshots are so
unusual it's not worth creating trees for those.

The mechanism is that I reuse the timings we track for
`enableProfilerCommitHooks`. I track first and last effect timestamp
within each component subtree. Then on the way up do we log the entry.
This means that we don't include overhead to find our way down to a
component and that we don't need to add any additional overhead by
reading timestamps.

To ensure that the entries get ordered correctly we need to ensure that
the start time of each parent is slightly before the inner one.

Author: sebmarkbage

packages/react-reconciler/src/ReactFiberCommitWork.js

@@ -99,13 +99,21 @@ import {
   Cloned,
 } from './ReactFiberFlags';
 import {
-  getCommitTime,
-  getCompleteTime,
+  commitTime,
+  completeTime,
   pushNestedEffectDurations,
   popNestedEffectDurations,
   bubbleNestedEffectDurations,
+  resetComponentEffectTimers,
+  pushComponentEffectStart,
+  popComponentEffectStart,
+  componentEffectStartTime,
+  componentEffectEndTime,
 } from './ReactProfilerTimer';
-import {logComponentRender} from './ReactFiberPerformanceTrack';
+import {
+  logComponentRender,
+  logComponentEffect,
+} from './ReactFiberPerformanceTrack';
 import {ConcurrentMode, NoMode, ProfileMode} from './ReactTypeOfMode';
 import {deferHiddenCallbacks} from './ReactFiberClassUpdateQueue';
 import {
@@ -382,6 +390,8 @@ function commitLayoutEffectOnFiber(
   finishedWork: Fiber,
   committedLanes: Lanes,
 ): void {
+  const prevEffectStart = pushComponentEffectStart();
+
   // When updating this function, also update reappearLayoutEffects, which does
   // most of the same things when an offscreen tree goes from hidden -> visible.
   const flags = finishedWork.flags;
@@ -494,7 +504,7 @@ function commitLayoutEffectOnFiber(
         commitProfilerUpdate(
           finishedWork,
           current,
-          getCommitTime(),
+          commitTime,
           profilerInstance.effectDuration,
         );
       } else {
@@ -585,6 +595,23 @@ function commitLayoutEffectOnFiber(
       break;
     }
   }
+
+  if (
+    enableProfilerTimer &&
+    enableProfilerCommitHooks &&
+    enableComponentPerformanceTrack &&
+    (finishedWork.mode & ProfileMode) !== NoMode &&
+    componentEffectStartTime >= 0 &&
+    componentEffectEndTime >= 0
+  ) {
+    logComponentEffect(
+      finishedWork,
+      componentEffectStartTime,
+      componentEffectEndTime,
+    );
+  }
+
+  popComponentEffectStart(prevEffectStart);
 }
 
 function abortRootTransitions(
@@ -1530,6 +1557,8 @@ export function commitMutationEffects(
   inProgressLanes = committedLanes;
   inProgressRoot = root;
 
+  resetComponentEffectTimers();
+
   commitMutationEffectsOnFiber(finishedWork, root, committedLanes);
 
   inProgressLanes = null;
@@ -1570,6 +1599,8 @@ function commitMutationEffectsOnFiber(
   root: FiberRoot,
   lanes: Lanes,
 ) {
+  const prevEffectStart = pushComponentEffectStart();
+
   const current = finishedWork.alternate;
   const flags = finishedWork.flags;
 
@@ -1598,7 +1629,7 @@ function commitMutationEffectsOnFiber(
           HookLayout | HookHasEffect,
         );
       }
-      return;
+      break;
     }
     case ClassComponent: {
       recursivelyTraverseMutationEffects(root, finishedWork, lanes);
@@ -1617,7 +1648,7 @@ function commitMutationEffectsOnFiber(
           deferHiddenCallbacks(updateQueue);
         }
       }
-      return;
+      break;
     }
     case HostHoistable: {
       if (supportsResources) {
@@ -1693,7 +1724,7 @@ function commitMutationEffectsOnFiber(
             );
           }
         }
-        return;
+        break;
       }
       // Fall through
     }
@@ -1756,7 +1787,7 @@ function commitMutationEffectsOnFiber(
           }
         }
       }
-      return;
+      break;
     }
     case HostText: {
       recursivelyTraverseMutationEffects(root, finishedWork, lanes);
@@ -1781,7 +1812,7 @@ function commitMutationEffectsOnFiber(
           commitHostTextUpdate(finishedWork, newText, oldText);
         }
       }
-      return;
+      break;
     }
     case HostRoot: {
       const prevEffectDuration = pushNestedEffectDurations();
@@ -1833,7 +1864,7 @@ function commitMutationEffectsOnFiber(
         root.effectDuration += popNestedEffectDurations(prevEffectDuration);
       }
 
-      return;
+      break;
     }
     case HostPortal: {
       if (supportsResources) {
@@ -1858,7 +1889,7 @@ function commitMutationEffectsOnFiber(
           );
         }
       }
-      return;
+      break;
     }
     case Profiler: {
       const prevEffectDuration = pushNestedEffectDurations();
@@ -1873,7 +1904,7 @@ function commitMutationEffectsOnFiber(
         profilerInstance.effectDuration +=
           bubbleNestedEffectDurations(prevEffectDuration);
       }
-      return;
+      break;
     }
     case SuspenseComponent: {
       recursivelyTraverseMutationEffects(root, finishedWork, lanes);
@@ -1925,7 +1956,7 @@ function commitMutationEffectsOnFiber(
           attachSuspenseRetryListeners(finishedWork, retryQueue);
         }
       }
-      return;
+      break;
     }
     case OffscreenComponent: {
       if (flags & Ref) {
@@ -2018,7 +2049,7 @@ function commitMutationEffectsOnFiber(
           }
         }
       }
-      return;
+      break;
     }
     case SuspenseListComponent: {
       recursivelyTraverseMutationEffects(root, finishedWork, lanes);
@@ -2032,7 +2063,7 @@ function commitMutationEffectsOnFiber(
           attachSuspenseRetryListeners(finishedWork, retryQueue);
         }
       }
-      return;
+      break;
     }
     case ScopeComponent: {
       if (enableScopeAPI) {
@@ -2052,16 +2083,34 @@ function commitMutationEffectsOnFiber(
           prepareScopeUpdate(scopeInstance, finishedWork);
         }
       }
-      return;
+      break;
     }
     default: {
       recursivelyTraverseMutationEffects(root, finishedWork, lanes);
       commitReconciliationEffects(finishedWork);
 
-      return;
+      break;
     }
   }
+
+  if (
+    enableProfilerTimer &&
+    enableProfilerCommitHooks &&
+    enableComponentPerformanceTrack &&
+    (finishedWork.mode & ProfileMode) !== NoMode &&
+    componentEffectStartTime >= 0 &&
+    componentEffectEndTime >= 0
+  ) {
+    logComponentEffect(
+      finishedWork,
+      componentEffectStartTime,
+      componentEffectEndTime,
+    );
+  }
+
+  popComponentEffectStart(prevEffectStart);
 }
+
 function commitReconciliationEffects(finishedWork: Fiber) {
   // Placement effects (insertions, reorders) can be scheduled on any fiber
   // type. They needs to happen after the children effects have fired, but
@@ -2106,6 +2155,8 @@ export function commitLayoutEffects(
   inProgressLanes = committedLanes;
   inProgressRoot = root;
 
+  resetComponentEffectTimers();
+
   const current = finishedWork.alternate;
   commitLayoutEffectOnFiber(root, current, finishedWork, committedLanes);
 
@@ -2291,7 +2342,7 @@ export function reappearLayoutEffects(
         commitProfilerUpdate(
           finishedWork,
           current,
-          getCommitTime(),
+          commitTime,
           profilerInstance.effectDuration,
         );
       } else {
@@ -2515,14 +2566,14 @@ export function commitPassiveMountEffects(
   committedLanes: Lanes,
   committedTransitions: Array<Transition> | null,
 ): void {
+  resetComponentEffectTimers();
+
   commitPassiveMountOnFiber(
     root,
     finishedWork,
     committedLanes,
     committedTransitions,
-    enableProfilerTimer && enableComponentPerformanceTrack
-      ? getCompleteTime()
-      : 0,
+    enableProfilerTimer && enableComponentPerformanceTrack ? completeTime : 0,
   );
 }
 
@@ -2577,6 +2628,8 @@ function commitPassiveMountOnFiber(
   committedTransitions: Array<Transition> | null,
   endTime: number, // Profiling-only. The start time of the next Fiber or root completion.
 ): void {
+  const prevEffectStart = pushComponentEffectStart();
+
   // If this component rendered in Profiling mode (DEV or in Profiler component) then log its
   // render time. We do this after the fact in the passive effect to avoid the overhead of this
   // getting in the way of the render characteristics and avoid the overhead of unwinding
@@ -2707,7 +2760,7 @@ function commitPassiveMountOnFiber(
           finishedWork.alternate,
           // This value will still reflect the previous commit phase.
           // It does not get reset until the start of the next commit phase.
-          getCommitTime(),
+          commitTime,
           profilerInstance.passiveEffectDuration,
         );
       } else {
@@ -2860,6 +2913,23 @@ function commitPassiveMountOnFiber(
       break;
     }
   }
+
+  if (
+    enableProfilerTimer &&
+    enableProfilerCommitHooks &&
+    enableComponentPerformanceTrack &&
+    (finishedWork.mode & ProfileMode) !== NoMode &&
+    componentEffectStartTime >= 0 &&
+    componentEffectEndTime >= 0
+  ) {
+    logComponentEffect(
+      finishedWork,
+      componentEffectStartTime,
+      componentEffectEndTime,
+    );
+  }
+
+  popComponentEffectStart(prevEffectStart);
 }
 
 function recursivelyTraverseReconnectPassiveEffects(
@@ -3131,6 +3201,7 @@ function commitAtomicPassiveEffects(
 }
 
 export function commitPassiveUnmountEffects(finishedWork: Fiber): void {
+  resetComponentEffectTimers();
   commitPassiveUnmountOnFiber(finishedWork);
 }
 
@@ -3289,6 +3360,8 @@ function recursivelyTraversePassiveUnmountEffects(parentFiber: Fiber): void {
 }
 
 function commitPassiveUnmountOnFiber(finishedWork: Fiber): void {
+  const prevEffectStart = pushComponentEffectStart();
+
   switch (finishedWork.tag) {
     case FunctionComponent:
     case ForwardRef:
@@ -3358,6 +3431,23 @@ function commitPassiveUnmountOnFiber(finishedWork: Fiber): void {
       break;
     }
   }
+
+  if (
+    enableProfilerTimer &&
+    enableProfilerCommitHooks &&
+    enableComponentPerformanceTrack &&
+    (finishedWork.mode & ProfileMode) !== NoMode &&
+    componentEffectStartTime >= 0 &&
+    componentEffectEndTime >= 0
+  ) {
+    logComponentEffect(
+      finishedWork,
+      componentEffectStartTime,
+      componentEffectEndTime,
+    );
+  }
+
+  popComponentEffectStart(prevEffectStart);
 }
 
 function recursivelyTraverseDisconnectPassiveEffects(parentFiber: Fiber): void {

packages/react-reconciler/src/ReactFiberPerformanceTrack.js

@@ -38,9 +38,24 @@ const reusableComponentOptions = {
   },
 };
 
+const reusableComponentEffectDevToolDetails = {
+  dataType: 'track-entry',
+  color: 'secondary',
+  track: 'Blocking', // Lane
+  trackGroup: TRACK_GROUP,
+};
+const reusableComponentEffectOptions = {
+  start: -0,
+  end: -0,
+  detail: {
+    devtools: reusableComponentEffectDevToolDetails,
+  },
+};
+
 export function setCurrentTrackFromLanes(lanes: number): void {
-  reusableComponentDevToolDetails.track =
-    getGroupNameOfHighestPriorityLane(lanes);
+  reusableComponentEffectDevToolDetails.track =
+    reusableComponentDevToolDetails.track =
+      getGroupNameOfHighestPriorityLane(lanes);
 }
 
 export function logComponentRender(
@@ -59,3 +74,20 @@ export function logComponentRender(
     performance.measure(name, reusableComponentOptions);
   }
 }
+
+export function logComponentEffect(
+  fiber: Fiber,
+  startTime: number,
+  endTime: number,
+): void {
+  const name = getComponentNameFromFiber(fiber);
+  if (name === null) {
+    // Skip
+    return;
+  }
+  if (supportsUserTiming) {
+    reusableComponentEffectOptions.start = startTime;
+    reusableComponentEffectOptions.end = endTime;
+    performance.measure(name, reusableComponentEffectOptions);
+  }
+}