Repository: facebook/react
Pull request: [Fiber] Log Component Effects to Performance Track

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.


Changed files:
filename: packages/react-reconciler/src/ReactFiberCommitWork.js
patch: @@ -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 {

filename: packages/react-reconciler/src/ReactFiberPerformanceTrack.js
patch: @@ -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);
+  }
+}

filename: packages/react-reconciler/src/ReactProfilerTimer.js
patch: @@ -21,25 +21,14 @@ import * as Scheduler from 'scheduler';
 
 const {unstable_now: now} = Scheduler;
 
-export type ProfilerTimer = {
-  getCommitTime(): number,
-  isCurrentUpdateNested(): boolean,
-  markNestedUpdateScheduled(): void,
-  recordCommitTime(): void,
-  startProfilerTimer(fiber: Fiber): void,
-  stopProfilerTimerIfRunning(fiber: Fiber): void,
-  stopProfilerTimerIfRunningAndRecordDuration(fiber: Fiber): void,
-  stopProfilerTimerIfRunningAndRecordIncompleteDuration(fiber: Fiber): void,
-  syncNestedUpdateFlag(): void,
-  ...
-};
-
-let completeTime: number = -0;
-let commitTime: number = -0;
-let profilerStartTime: number = -1.1;
-let profilerEffectDuration: number = -0;
-
-function pushNestedEffectDurations(): number {
+export let completeTime: number = -0;
+export let commitTime: number = -0;
+export let profilerStartTime: number = -1.1;
+export let profilerEffectDuration: number = -0;
+export let componentEffectStartTime: number = -1.1;
+export let componentEffectEndTime: number = -1.1;
+
+export function pushNestedEffectDurations(): number {
   if (!enableProfilerTimer || !enableProfilerCommitHooks) {
     return 0;
   }
@@ -48,7 +37,7 @@ function pushNestedEffectDurations(): number {
   return prevEffectDuration;
 }
 
-function popNestedEffectDurations(prevEffectDuration: number): number {
+export function popNestedEffectDurations(prevEffectDuration: number): number {
   if (!enableProfilerTimer || !enableProfilerCommitHooks) {
     return 0;
   }
@@ -58,7 +47,9 @@ function popNestedEffectDurations(prevEffectDuration: number): number {
 }
 
 // Like pop but it also adds the current elapsed time to the parent scope.
-function bubbleNestedEffectDurations(prevEffectDuration: number): number {
+export function bubbleNestedEffectDurations(
+  prevEffectDuration: number,
+): number {
   if (!enableProfilerTimer || !enableProfilerCommitHooks) {
     return 0;
   }
@@ -67,6 +58,39 @@ function bubbleNestedEffectDurations(prevEffectDuration: number): number {
   return elapsedTime;
 }
 
+export function resetComponentEffectTimers(): void {
+  if (!enableProfilerTimer || !enableProfilerCommitHooks) {
+    return;
+  }
+  componentEffectStartTime = -1.1;
+  componentEffectEndTime = -1.1;
+}
+
+export function pushComponentEffectStart(): number {
+  if (!enableProfilerTimer || !enableProfilerCommitHooks) {
+    return 0;
+  }
+  const prevEffectStart = componentEffectStartTime;
+  componentEffectStartTime = -1.1; // Track the next start.
+  return prevEffectStart;
+}
+
+export function popComponentEffectStart(prevEffectStart: number): void {
+  if (!enableProfilerTimer || !enableProfilerCommitHooks) {
+    return;
+  }
+  if (prevEffectStart < 0) {
+    // If the parent component didn't have a start time, we use the start
+    // of the child as the parent's start time. We subtrack a minimal amount of
+    // time to ensure that the parent's start time is before the child to ensure
+    // that the performance tracks line up in the right order.
+    componentEffectStartTime -= 0.001;
+  } else {
+    // Otherwise, we restore the previous parent's start time.
+    componentEffectStartTime = prevEffectStart;
+  }
+}
+
 /**
  * Tracks whether the current update was a nested/cascading update (scheduled from a layout effect).
  *
@@ -86,53 +110,45 @@ function bubbleNestedEffectDurations(prevEffectDuration: number): number {
 let currentUpdateIsNested: boolean = false;
 let nestedUpdateScheduled: boolean = false;
 
-function isCurrentUpdateNested(): boolean {
+export function isCurrentUpdateNested(): boolean {
   return currentUpdateIsNested;
 }
 
-function markNestedUpdateScheduled(): void {
+export function markNestedUpdateScheduled(): void {
   if (enableProfilerNestedUpdatePhase) {
     nestedUpdateScheduled = true;
   }
 }
 
-function resetNestedUpdateFlag(): void {
+export function resetNestedUpdateFlag(): void {
   if (enableProfilerNestedUpdatePhase) {
     currentUpdateIsNested = false;
     nestedUpdateScheduled = false;
   }
 }
 
-function syncNestedUpdateFlag(): void {
+export function syncNestedUpdateFlag(): void {
   if (enableProfilerNestedUpdatePhase) {
     currentUpdateIsNested = nestedUpdateScheduled;
     nestedUpdateScheduled = false;
   }
 }
 
-function getCompleteTime(): number {
-  return completeTime;
-}
-
-function recordCompleteTime(): void {
+export function recordCompleteTime(): void {
   if (!enableProfilerTimer) {
     return;
   }
   completeTime = now();
 }
 
-function getCommitTime(): number {
-  return commitTime;
-}
-
-function recordCommitTime(): void {
+export function recordCommitTime(): void {
   if (!enableProfilerTimer) {
     return;
   }
   commitTime = now();
 }
 
-function startProfilerTimer(fiber: Fiber): void {
+export function startProfilerTimer(fiber: Fiber): void {
   if (!enableProfilerTimer) {
     return;
   }
@@ -144,14 +160,16 @@ function startProfilerTimer(fiber: Fiber): void {
   }
 }
 
-function stopProfilerTimerIfRunning(fiber: Fiber): void {
+export function stopProfilerTimerIfRunning(fiber: Fiber): void {
   if (!enableProfilerTimer) {
     return;
   }
   profilerStartTime = -1;
 }
 
-function stopProfilerTimerIfRunningAndRecordDuration(fiber: Fiber): void {
+export function stopProfilerTimerIfRunningAndRecordDuration(
+  fiber: Fiber,
+): void {
   if (!enableProfilerTimer) {
     return;
   }
@@ -164,7 +182,7 @@ function stopProfilerTimerIfRunningAndRecordDuration(fiber: Fiber): void {
   }
 }
 
-function stopProfilerTimerIfRunningAndRecordIncompleteDuration(
+export function stopProfilerTimerIfRunningAndRecordIncompleteDuration(
   fiber: Fiber,
 ): void {
   if (!enableProfilerTimer) {
@@ -179,30 +197,38 @@ function stopProfilerTimerIfRunningAndRecordIncompleteDuration(
   }
 }
 
-function recordEffectDuration(fiber: Fiber): void {
+export function recordEffectDuration(fiber: Fiber): void {
   if (!enableProfilerTimer || !enableProfilerCommitHooks) {
     return;
   }
 
   if (profilerStartTime >= 0) {
-    const elapsedTime = now() - profilerStartTime;
+    const endTime = now();
+    const elapsedTime = endTime - profilerStartTime;
 
     profilerStartTime = -1;
 
     // Store duration on the next nearest Profiler ancestor
     // Or the root (for the DevTools Profiler to read)
     profilerEffectDuration += elapsedTime;
+
+    // Keep track of the last end time of the effects.
+    componentEffectEndTime = endTime;
   }
 }
 
-function startEffectTimer(): void {
+export function startEffectTimer(): void {
   if (!enableProfilerTimer || !enableProfilerCommitHooks) {
     return;
   }
   profilerStartTime = now();
+  if (componentEffectStartTime < 0) {
+    // Keep track of the first time we start an effect as the component's effect start time.
+    componentEffectStartTime = profilerStartTime;
+  }
 }
 
-function transferActualDuration(fiber: Fiber): void {
+export function transferActualDuration(fiber: Fiber): void {
   // Transfer time spent rendering these children so we don't lose it
   // after we rerender. This is used as a helper in special cases
   // where we should count the work of multiple passes.
@@ -213,24 +239,3 @@ function transferActualDuration(fiber: Fiber): void {
     child = child.sibling;
   }
 }
-
-export {
-  getCompleteTime,
-  recordCompleteTime,
-  getCommitTime,
-  recordCommitTime,
-  isCurrentUpdateNested,
-  markNestedUpdateScheduled,
-  recordEffectDuration,
-  resetNestedUpdateFlag,
-  startEffectTimer,
-  startProfilerTimer,
-  stopProfilerTimerIfRunning,
-  stopProfilerTimerIfRunningAndRecordDuration,
-  stopProfilerTimerIfRunningAndRecordIncompleteDuration,
-  syncNestedUpdateFlag,
-  transferActualDuration,
-  pushNestedEffectDurations,
-  popNestedEffectDurations,
-  bubbleNestedEffectDurations,
-};