Repository: facebook/react
Pull request: [Perf Tracks]: Always log effect that spawned blocking update

We've observed some scenarios, where cascading update happens in an effect that was shorter than 0.05ms. In this case, this effect won't be displayed on a timeline, because of the threshold that we are using, but it would be shown in entry properties or in a stack trace.

To avoid confusion, we should always log such effects.

Validated via manually changing the threshold to 100ms+ and observing that only effects that triggered an update are visible on a timeline.


Changed files:
filename: packages/react-reconciler/src/ReactFiberCommitWork.js
patch: @@ -130,10 +130,13 @@ import {
   popComponentEffectDuration,
   pushComponentEffectErrors,
   popComponentEffectErrors,
+  pushComponentEffectDidSpawnUpdate,
+  popComponentEffectDidSpawnUpdate,
   componentEffectStartTime,
   componentEffectEndTime,
   componentEffectDuration,
   componentEffectErrors,
+  componentEffectSpawnedUpdate,
 } from './ReactProfilerTimer';
 import {
   logComponentRender,
@@ -595,6 +598,7 @@ function commitLayoutEffectOnFiber(
   const prevEffectStart = pushComponentEffectStart();
   const prevEffectDuration = pushComponentEffectDuration();
   const prevEffectErrors = pushComponentEffectErrors();
+  const prevEffectDidSpawnUpdate = pushComponentEffectDidSpawnUpdate();
   // 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;
@@ -876,7 +880,7 @@ function commitLayoutEffectOnFiber(
     componentEffectStartTime >= 0 &&
     componentEffectEndTime >= 0
   ) {
-    if (componentEffectDuration > 0.05) {
+    if (componentEffectSpawnedUpdate || componentEffectDuration > 0.05) {
       logComponentEffect(
         finishedWork,
         componentEffectStartTime,
@@ -909,6 +913,7 @@ function commitLayoutEffectOnFiber(
   popComponentEffectStart(prevEffectStart);
   popComponentEffectDuration(prevEffectDuration);
   popComponentEffectErrors(prevEffectErrors);
+  popComponentEffectDidSpawnUpdate(prevEffectDidSpawnUpdate);
 }
 
 function abortRootTransitions(
@@ -1430,6 +1435,7 @@ function commitDeletionEffectsOnFiber(
   const prevEffectStart = pushComponentEffectStart();
   const prevEffectDuration = pushComponentEffectDuration();
   const prevEffectErrors = pushComponentEffectErrors();
+  const prevEffectDidSpawnUpdate = pushComponentEffectDidSpawnUpdate();
 
   // The cases in this outer switch modify the stack before they traverse
   // into their subtree. There are simpler cases in the inner switch
@@ -1750,7 +1756,7 @@ function commitDeletionEffectsOnFiber(
     (deletedFiber.mode & ProfileMode) !== NoMode &&
     componentEffectStartTime >= 0 &&
     componentEffectEndTime >= 0 &&
-    componentEffectDuration > 0.05
+    (componentEffectSpawnedUpdate || componentEffectDuration > 0.05)
   ) {
     logComponentEffect(
       deletedFiber,
@@ -1764,6 +1770,7 @@ function commitDeletionEffectsOnFiber(
   popComponentEffectStart(prevEffectStart);
   popComponentEffectDuration(prevEffectDuration);
   popComponentEffectErrors(prevEffectErrors);
+  popComponentEffectDidSpawnUpdate(prevEffectDidSpawnUpdate);
 }
 
 function commitSuspenseCallback(finishedWork: Fiber) {
@@ -1987,6 +1994,7 @@ function commitMutationEffectsOnFiber(
   const prevEffectStart = pushComponentEffectStart();
   const prevEffectDuration = pushComponentEffectDuration();
   const prevEffectErrors = pushComponentEffectErrors();
+  const prevEffectDidSpawnUpdate = pushComponentEffectDidSpawnUpdate();
   const current = finishedWork.alternate;
   const flags = finishedWork.flags;
 
@@ -2611,7 +2619,7 @@ function commitMutationEffectsOnFiber(
     componentEffectStartTime >= 0 &&
     componentEffectEndTime >= 0
   ) {
-    if (componentEffectDuration > 0.05) {
+    if (componentEffectSpawnedUpdate || componentEffectDuration > 0.05) {
       logComponentEffect(
         finishedWork,
         componentEffectStartTime,
@@ -2644,6 +2652,7 @@ function commitMutationEffectsOnFiber(
   popComponentEffectStart(prevEffectStart);
   popComponentEffectDuration(prevEffectDuration);
   popComponentEffectErrors(prevEffectErrors);
+  popComponentEffectDidSpawnUpdate(prevEffectDidSpawnUpdate);
 }
 
 function commitReconciliationEffects(
@@ -2900,6 +2909,7 @@ export function disappearLayoutEffects(finishedWork: Fiber) {
   const prevEffectStart = pushComponentEffectStart();
   const prevEffectDuration = pushComponentEffectDuration();
   const prevEffectErrors = pushComponentEffectErrors();
+  const prevEffectDidSpawnUpdate = pushComponentEffectDidSpawnUpdate();
   switch (finishedWork.tag) {
     case FunctionComponent:
     case ForwardRef:
@@ -2990,7 +3000,7 @@ export function disappearLayoutEffects(finishedWork: Fiber) {
     (finishedWork.mode & ProfileMode) !== NoMode &&
     componentEffectStartTime >= 0 &&
     componentEffectEndTime >= 0 &&
-    componentEffectDuration > 0.05
+    (componentEffectSpawnedUpdate || componentEffectDuration > 0.05)
   ) {
     logComponentEffect(
       finishedWork,
@@ -3004,6 +3014,7 @@ export function disappearLayoutEffects(finishedWork: Fiber) {
   popComponentEffectStart(prevEffectStart);
   popComponentEffectDuration(prevEffectDuration);
   popComponentEffectErrors(prevEffectErrors);
+  popComponentEffectDidSpawnUpdate(prevEffectDidSpawnUpdate);
 }
 
 function recursivelyTraverseDisappearLayoutEffects(parentFiber: Fiber) {
@@ -3027,6 +3038,7 @@ export function reappearLayoutEffects(
   const prevEffectStart = pushComponentEffectStart();
   const prevEffectDuration = pushComponentEffectDuration();
   const prevEffectErrors = pushComponentEffectErrors();
+  const prevEffectDidSpawnUpdate = pushComponentEffectDidSpawnUpdate();
   // Turn on layout effects in a tree that previously disappeared.
   const flags = finishedWork.flags;
   switch (finishedWork.tag) {
@@ -3224,7 +3236,7 @@ export function reappearLayoutEffects(
     (finishedWork.mode & ProfileMode) !== NoMode &&
     componentEffectStartTime >= 0 &&
     componentEffectEndTime >= 0 &&
-    componentEffectDuration > 0.05
+    (componentEffectSpawnedUpdate || componentEffectDuration > 0.05)
   ) {
     logComponentEffect(
       finishedWork,
@@ -3238,6 +3250,7 @@ export function reappearLayoutEffects(
   popComponentEffectStart(prevEffectStart);
   popComponentEffectDuration(prevEffectDuration);
   popComponentEffectErrors(prevEffectErrors);
+  popComponentEffectDidSpawnUpdate(prevEffectDidSpawnUpdate);
 }
 
 function recursivelyTraverseReappearLayoutEffects(
@@ -3489,6 +3502,7 @@ function commitPassiveMountOnFiber(
   const prevEffectStart = pushComponentEffectStart();
   const prevEffectDuration = pushComponentEffectDuration();
   const prevEffectErrors = pushComponentEffectErrors();
+  const prevEffectDidSpawnUpdate = pushComponentEffectDidSpawnUpdate();
   const prevDeepEquality = pushDeepEquality();
 
   const isViewTransitionEligible = enableViewTransition
@@ -4060,7 +4074,7 @@ function commitPassiveMountOnFiber(
       }
     }
     if (componentEffectStartTime >= 0 && componentEffectEndTime >= 0) {
-      if (componentEffectDuration > 0.05) {
+      if (componentEffectSpawnedUpdate || componentEffectDuration > 0.05) {
         logComponentEffect(
           finishedWork,
           componentEffectStartTime,
@@ -4082,6 +4096,7 @@ function commitPassiveMountOnFiber(
   popComponentEffectStart(prevEffectStart);
   popComponentEffectDuration(prevEffectDuration);
   popComponentEffectErrors(prevEffectErrors);
+  popComponentEffectDidSpawnUpdate(prevEffectDidSpawnUpdate);
   popDeepEquality(prevDeepEquality);
 }
 
@@ -4144,6 +4159,7 @@ export function reconnectPassiveEffects(
   const prevEffectStart = pushComponentEffectStart();
   const prevEffectDuration = pushComponentEffectDuration();
   const prevEffectErrors = pushComponentEffectErrors();
+  const prevEffectDidSpawnUpdate = pushComponentEffectDidSpawnUpdate();
   const prevDeepEquality = pushDeepEquality();
 
   // If this component rendered in Profiling mode (DEV or in Profiler component) then log its
@@ -4334,7 +4350,7 @@ export function reconnectPassiveEffects(
     (finishedWork.mode & ProfileMode) !== NoMode &&
     componentEffectStartTime >= 0 &&
     componentEffectEndTime >= 0 &&
-    componentEffectDuration > 0.05
+    (componentEffectSpawnedUpdate || componentEffectDuration > 0.05)
   ) {
     logComponentEffect(
       finishedWork,
@@ -4348,6 +4364,7 @@ export function reconnectPassiveEffects(
   popComponentEffectStart(prevEffectStart);
   popComponentEffectDuration(prevEffectDuration);
   popComponentEffectErrors(prevEffectErrors);
+  popComponentEffectDidSpawnUpdate(prevEffectDidSpawnUpdate);
   popDeepEquality(prevDeepEquality);
 }
 
@@ -4737,6 +4754,7 @@ function commitPassiveUnmountOnFiber(finishedWork: Fiber): void {
   const prevEffectStart = pushComponentEffectStart();
   const prevEffectDuration = pushComponentEffectDuration();
   const prevEffectErrors = pushComponentEffectErrors();
+  const prevEffectDidSpawnUpdate = pushComponentEffectDidSpawnUpdate();
   switch (finishedWork.tag) {
     case FunctionComponent:
     case ForwardRef:
@@ -4833,7 +4851,7 @@ function commitPassiveUnmountOnFiber(finishedWork: Fiber): void {
     (finishedWork.mode & ProfileMode) !== NoMode &&
     componentEffectStartTime >= 0 &&
     componentEffectEndTime >= 0 &&
-    componentEffectDuration > 0.05
+    (componentEffectSpawnedUpdate || componentEffectDuration > 0.05)
   ) {
     logComponentEffect(
       finishedWork,
@@ -4846,6 +4864,7 @@ function commitPassiveUnmountOnFiber(finishedWork: Fiber): void {
 
   popComponentEffectStart(prevEffectStart);
   popComponentEffectDuration(prevEffectDuration);
+  popComponentEffectDidSpawnUpdate(prevEffectDidSpawnUpdate);
   popComponentEffectErrors(prevEffectErrors);
 }
 
@@ -4903,6 +4922,7 @@ export function disconnectPassiveEffect(finishedWork: Fiber): void {
   const prevEffectStart = pushComponentEffectStart();
   const prevEffectDuration = pushComponentEffectDuration();
   const prevEffectErrors = pushComponentEffectErrors();
+  const prevEffectDidSpawnUpdate = pushComponentEffectDidSpawnUpdate();
 
   switch (finishedWork.tag) {
     case FunctionComponent:
@@ -4942,7 +4962,7 @@ export function disconnectPassiveEffect(finishedWork: Fiber): void {
     (finishedWork.mode & ProfileMode) !== NoMode &&
     componentEffectStartTime >= 0 &&
     componentEffectEndTime >= 0 &&
-    componentEffectDuration > 0.05
+    (componentEffectSpawnedUpdate || componentEffectDuration > 0.05)
   ) {
     logComponentEffect(
       finishedWork,
@@ -4955,6 +4975,7 @@ export function disconnectPassiveEffect(finishedWork: Fiber): void {
 
   popComponentEffectStart(prevEffectStart);
   popComponentEffectDuration(prevEffectDuration);
+  popComponentEffectDidSpawnUpdate(prevEffectDidSpawnUpdate);
   popComponentEffectErrors(prevEffectErrors);
 }
 
@@ -5016,6 +5037,7 @@ function commitPassiveUnmountInsideDeletedTreeOnFiber(
   const prevEffectStart = pushComponentEffectStart();
   const prevEffectDuration = pushComponentEffectDuration();
   const prevEffectErrors = pushComponentEffectErrors();
+  const prevEffectDidSpawnUpdate = pushComponentEffectDidSpawnUpdate();
   switch (current.tag) {
     case FunctionComponent:
     case ForwardRef:
@@ -5135,7 +5157,7 @@ function commitPassiveUnmountInsideDeletedTreeOnFiber(
     (current.mode & ProfileMode) !== NoMode &&
     componentEffectStartTime >= 0 &&
     componentEffectEndTime >= 0 &&
-    componentEffectDuration > 0.05
+    (componentEffectSpawnedUpdate || componentEffectDuration > 0.05)
   ) {
     logComponentEffect(
       current,
@@ -5148,6 +5170,7 @@ function commitPassiveUnmountInsideDeletedTreeOnFiber(
 
   popComponentEffectStart(prevEffectStart);
   popComponentEffectDuration(prevEffectDuration);
+  popComponentEffectDidSpawnUpdate(prevEffectDidSpawnUpdate);
   popComponentEffectErrors(prevEffectErrors);
 }
 

filename: packages/react-reconciler/src/ReactProfilerTimer.js
patch: @@ -64,6 +64,7 @@ export let componentEffectDuration: number = -0;
 export let componentEffectStartTime: number = -1.1;
 export let componentEffectEndTime: number = -1.1;
 export let componentEffectErrors: null | Array<CapturedValue<mixed>> = null;
+export let componentEffectSpawnedUpdate: boolean = false;
 
 export let blockingClampTime: number = -0;
 export let blockingUpdateTime: number = -1.1; // First sync setState scheduled.
@@ -153,6 +154,7 @@ export function startUpdateTimerByLane(
         blockingUpdateComponentName = getComponentNameFromFiber(fiber);
       }
       if (isAlreadyRendering()) {
+        componentEffectSpawnedUpdate = true;
         blockingUpdateType = SPAWNED_UPDATE;
       }
       const newEventTime = resolveEventTimeStamp();
@@ -495,6 +497,24 @@ export function popComponentEffectErrors(
   componentEffectErrors = prevErrors;
 }
 
+export function pushComponentEffectDidSpawnUpdate(): boolean {
+  if (!enableProfilerTimer || !enableProfilerCommitHooks) {
+    return false;
+  }
+
+  const prev = componentEffectSpawnedUpdate;
+  componentEffectSpawnedUpdate = false; // Reset.
+  return prev;
+}
+
+export function popComponentEffectDidSpawnUpdate(previousValue: boolean): void {
+  if (!enableProfilerTimer || !enableProfilerCommitHooks) {
+    return;
+  }
+
+  componentEffectSpawnedUpdate = previousValue;
+}
+
 /**
  * Tracks whether the current update was a nested/cascading update (scheduled from a layout effect).
  *