Fix Overlapping "message" Bug in Performance Track (#31528)

sebmarkbage · web-flow · commit c13986da7866 · 2024-11-14T16:35:08.000-05:00
When you schedule a microtask from render or effect and then call setState (or ping) from there, the "event" is the event that React scheduled (which will be a postMessage). The event time of this new render will be before the last render finished. We usually clamp these but in this scenario the update doesn't happen while a render is happening. Causing overlapping events. Before: <img width="1229" alt="Screenshot 2024-11-12 at 11 01 30 PM" src="https://github.com/user-attachments/assets/9652cf3b-b358-453c-b295-1239cbb15952"> Therefore when we finalize a render we need to store the end of the last render so when we a new update comes in later with an event time earlier than that, we know to clamp it. There's also a special case here where when we enter the `RootDidNotComplete` or `RootSuspendedWithDelay` case we neither leave the root as in progress nor commit it. Those needs to finalize too. Really this should be modeled as a suspended track that we haven't added yet. That's the gap between "Blocked" and "message" below. After: <img width="1471" alt="Screenshot 2024-11-13 at 12 31 34 AM" src="https://github.com/user-attachments/assets/b24f994e-9055-4b10-ad29-ad9b36302ffc"> I also fixed an issue where we may log the same event name multiple times if we're rendering more than once in the same event. In this case I just leave a blank trace between the last commit and the next update. I also adding ignoring of the "message" event at all in these cases when the event is from React's scheduling itself.
diff --git a/packages/react-art/src/ReactFiberConfigART.js b/packages/react-art/src/ReactFiberConfigART.js
@@ -363,6 +363,8 @@ export function resolveUpdatePriority(): EventPriority {
   return currentUpdatePriority || DefaultEventPriority;
 }
 
+export function trackSchedulerEvent(): void {}
+
 export function resolveEventType(): null | string {
   return null;
 }
diff --git a/packages/react-dom-bindings/src/client/ReactFiberConfigDOM.js b/packages/react-dom-bindings/src/client/ReactFiberConfigDOM.js
@@ -606,14 +606,19 @@ export function shouldAttemptEagerTransition(): boolean {
   return false;
 }
 
+let schedulerEvent: void | Event = undefined;
+export function trackSchedulerEvent(): void {
+  schedulerEvent = window.event;
+}
+
 export function resolveEventType(): null | string {
   const event = window.event;
-  return event ? event.type : null;
+  return event && event !== schedulerEvent ? event.type : null;
 }
 
 export function resolveEventTimeStamp(): number {
   const event = window.event;
-  return event ? event.timeStamp : -1.1;
+  return event && event !== schedulerEvent ? event.timeStamp : -1.1;
 }
 
 export const isPrimaryRenderer = true;
diff --git a/packages/react-native-renderer/src/ReactFiberConfigFabric.js b/packages/react-native-renderer/src/ReactFiberConfigFabric.js
@@ -372,6 +372,8 @@ export function resolveUpdatePriority(): EventPriority {
   return DefaultEventPriority;
 }
 
+export function trackSchedulerEvent(): void {}
+
 export function resolveEventType(): null | string {
   return null;
 }
diff --git a/packages/react-native-renderer/src/ReactFiberConfigNative.js b/packages/react-native-renderer/src/ReactFiberConfigNative.js
@@ -288,6 +288,8 @@ export function resolveUpdatePriority(): EventPriority {
   return DefaultEventPriority;
 }
 
+export function trackSchedulerEvent(): void {}
+
 export function resolveEventType(): null | string {
   return null;
 }
diff --git a/packages/react-noop-renderer/src/createReactNoop.js b/packages/react-noop-renderer/src/createReactNoop.js
@@ -531,6 +531,8 @@ function createReactNoop(reconciler: Function, useMutation: boolean) {
       return currentEventPriority;
     },
 
+    trackSchedulerEvent(): void {},
+
     resolveEventType(): null | string {
       return null;
     },
diff --git a/packages/react-reconciler/src/ReactFiberPerformanceTrack.js b/packages/react-reconciler/src/ReactFiberPerformanceTrack.js
@@ -118,6 +118,7 @@ export function logBlockingStart(
   updateTime: number,
   eventTime: number,
   eventType: null | string,
+  eventIsRepeat: boolean,
   renderStartTime: number,
 ): void {
   if (supportsUserTiming) {
@@ -127,7 +128,7 @@ export function logBlockingStart(
       reusableLaneDevToolDetails.color = 'secondary-dark';
       reusableLaneOptions.start = eventTime;
       reusableLaneOptions.end = updateTime > 0 ? updateTime : renderStartTime;
-      performance.measure(eventType, reusableLaneOptions);
+      performance.measure(eventIsRepeat ? '' : eventType, reusableLaneOptions);
     }
     if (updateTime > 0) {
       // Log the time from when we called setState until we started rendering.
@@ -144,6 +145,7 @@ export function logTransitionStart(
   updateTime: number,
   eventTime: number,
   eventType: null | string,
+  eventIsRepeat: boolean,
   renderStartTime: number,
 ): void {
   if (supportsUserTiming) {
@@ -158,7 +160,7 @@ export function logTransitionStart(
           : updateTime > 0
             ? updateTime
             : renderStartTime;
-      performance.measure(eventType, reusableLaneOptions);
+      performance.measure(eventIsRepeat ? '' : eventType, reusableLaneOptions);
     }
     if (startTime > 0) {
       // Log the time from when we started an async transition until we called setState or started rendering.
diff --git a/packages/react-reconciler/src/ReactFiberRootScheduler.js b/packages/react-reconciler/src/ReactFiberRootScheduler.js
@@ -18,6 +18,7 @@ import {
   disableSchedulerTimeoutInWorkLoop,
   enableProfilerTimer,
   enableProfilerNestedUpdatePhase,
+  enableComponentPerformanceTrack,
   enableSiblingPrerendering,
 } from 'shared/ReactFeatureFlags';
 import {
@@ -64,6 +65,7 @@ import {
   supportsMicrotasks,
   scheduleMicrotask,
   shouldAttemptEagerTransition,
+  trackSchedulerEvent,
 } from './ReactFiberConfig';
 
 import ReactSharedInternals from 'shared/ReactSharedInternals';
@@ -225,6 +227,12 @@ function flushSyncWorkAcrossRoots_impl(
 }
 
 function processRootScheduleInMicrotask() {
+  if (enableProfilerTimer && enableComponentPerformanceTrack) {
+    // Track the currently executing event if there is one so we can ignore this
+    // event when logging events.
+    trackSchedulerEvent();
+  }
+
   // This function is always called inside a microtask. It should never be
   // called synchronously.
   didScheduleMicrotask = false;
@@ -428,6 +436,12 @@ function performWorkOnRootViaSchedulerTask(
     resetNestedUpdateFlag();
   }
 
+  if (enableProfilerTimer && enableComponentPerformanceTrack) {
+    // Track the currently executing event if there is one so we can ignore this
+    // event when logging events.
+    trackSchedulerEvent();
+  }
+
   // Flush any pending passive effects before deciding which lanes to work on,
   // in case they schedule additional work.
   const originalCallbackNode = root.callbackNode;
diff --git a/packages/react-reconciler/src/ReactFiberWorkLoop.js b/packages/react-reconciler/src/ReactFiberWorkLoop.js
@@ -90,6 +90,7 @@ import {
   setCurrentUpdatePriority,
   getCurrentUpdatePriority,
   resolveUpdatePriority,
+  trackSchedulerEvent,
 } from './ReactFiberConfig';
 
 import {createWorkInProgress, resetWorkInProgress} from './ReactFiber';
@@ -229,13 +230,17 @@ import {
 } from './ReactFiberConcurrentUpdates';
 
 import {
+  blockingClampTime,
   blockingUpdateTime,
   blockingEventTime,
   blockingEventType,
+  blockingEventIsRepeat,
+  transitionClampTime,
   transitionStartTime,
   transitionUpdateTime,
   transitionEventTime,
   transitionEventType,
+  transitionEventIsRepeat,
   clearBlockingTimers,
   clearTransitionTimers,
   clampBlockingTimers,
@@ -938,6 +943,9 @@ export function performWorkOnRoot(
       }
       break;
     } else if (exitStatus === RootDidNotComplete) {
+      if (enableProfilerTimer && enableComponentPerformanceTrack) {
+        finalizeRender(lanes, now());
+      }
       // The render unwound without completing the tree. This happens in special
       // cases where need to exit the current render without producing a
       // consistent tree or committing.
@@ -1130,6 +1138,9 @@ function finishConcurrentRender(
         // This is a transition, so we should exit without committing a
         // placeholder and without scheduling a timeout. Delay indefinitely
         // until we receive more data.
+        if (enableProfilerTimer && enableComponentPerformanceTrack) {
+          finalizeRender(lanes, now());
+        }
         const didAttemptEntireTree =
           !workInProgressRootDidSkipSuspendedSiblings;
         markRootSuspended(
@@ -1655,19 +1666,31 @@ function prepareFreshStack(root: FiberRoot, lanes: Lanes): Fiber {
 
     if (includesSyncLane(lanes) || includesBlockingLane(lanes)) {
       logBlockingStart(
-        blockingUpdateTime,
-        blockingEventTime,
+        blockingUpdateTime >= 0 && blockingUpdateTime < blockingClampTime
+          ? blockingClampTime
+          : blockingUpdateTime,
+        blockingEventTime >= 0 && blockingEventTime < blockingClampTime
+          ? blockingClampTime
+          : blockingEventTime,
         blockingEventType,
+        blockingEventIsRepeat,
         renderStartTime,
       );
       clearBlockingTimers();
     }
     if (includesTransitionLane(lanes)) {
       logTransitionStart(
-        transitionStartTime,
-        transitionUpdateTime,
-        transitionEventTime,
+        transitionStartTime >= 0 && transitionStartTime < transitionClampTime
+          ? transitionClampTime
+          : transitionStartTime,
+        transitionUpdateTime >= 0 && transitionUpdateTime < transitionClampTime
+          ? transitionClampTime
+          : transitionUpdateTime,
+        transitionEventTime >= 0 && transitionEventTime < transitionClampTime
+          ? transitionClampTime
+          : transitionEventTime,
         transitionEventType,
+        transitionEventIsRepeat,
         renderStartTime,
       );
       clearTransitionTimers();
@@ -3139,6 +3162,11 @@ function commitRootImpl(
       // with setTimeout
       pendingPassiveTransitions = transitions;
       scheduleCallback(NormalSchedulerPriority, () => {
+        if (enableProfilerTimer && enableComponentPerformanceTrack) {
+          // Track the currently executing event if there is one so we can ignore this
+          // event when logging events.
+          trackSchedulerEvent();
+        }
         flushPassiveEffects(true);
         // This render triggered passive effects: release the root cache pool
         // *after* passive effects fire to avoid freeing a cache pool that may
diff --git a/packages/react-reconciler/src/ReactProfilerTimer.js b/packages/react-reconciler/src/ReactProfilerTimer.js
@@ -36,14 +36,18 @@ export let componentEffectDuration: number = -0;
 export let componentEffectStartTime: number = -1.1;
 export let componentEffectEndTime: number = -1.1;
 
+export let blockingClampTime: number = -0;
 export let blockingUpdateTime: number = -1.1; // First sync setState scheduled.
 export let blockingEventTime: number = -1.1; // Event timeStamp of the first setState.
 export let blockingEventType: null | string = null; // Event type of the first setState.
+export let blockingEventIsRepeat: boolean = false;
 // TODO: This should really be one per Transition lane.
+export let transitionClampTime: number = -0;
 export let transitionStartTime: number = -1.1; // First startTransition call before setState.
 export let transitionUpdateTime: number = -1.1; // First transition setState scheduled.
 export let transitionEventTime: number = -1.1; // Event timeStamp of the first transition.
 export let transitionEventType: null | string = null; // Event type of the first transition.
+export let transitionEventIsRepeat: boolean = false;
 
 export function startUpdateTimerByLane(lane: Lane): void {
   if (!enableProfilerTimer || !enableComponentPerformanceTrack) {
@@ -52,15 +56,25 @@ export function startUpdateTimerByLane(lane: Lane): void {
   if (isSyncLane(lane) || isBlockingLane(lane)) {
     if (blockingUpdateTime < 0) {
       blockingUpdateTime = now();
-      blockingEventTime = resolveEventTimeStamp();
-      blockingEventType = resolveEventType();
+      const newEventTime = resolveEventTimeStamp();
+      const newEventType = resolveEventType();
+      blockingEventIsRepeat =
+        newEventTime === blockingEventTime &&
+        newEventType === blockingEventType;
+      blockingEventTime = newEventTime;
+      blockingEventType = newEventType;
     }
   } else if (isTransitionLane(lane)) {
     if (transitionUpdateTime < 0) {
       transitionUpdateTime = now();
       if (transitionStartTime < 0) {
-        transitionEventTime = resolveEventTimeStamp();
-        transitionEventType = resolveEventType();
+        const newEventTime = resolveEventTimeStamp();
+        const newEventType = resolveEventType();
+        transitionEventIsRepeat =
+          newEventTime === transitionEventTime &&
+          newEventType === transitionEventType;
+        transitionEventTime = newEventTime;
+        transitionEventType = newEventType;
       }
     }
   }
@@ -76,8 +90,13 @@ export function startAsyncTransitionTimer(): void {
   }
   if (transitionStartTime < 0 && transitionUpdateTime < 0) {
     transitionStartTime = now();
-    transitionEventTime = resolveEventTimeStamp();
-    transitionEventType = resolveEventType();
+    const newEventTime = resolveEventTimeStamp();
+    const newEventType = resolveEventType();
+    transitionEventIsRepeat =
+      newEventTime === transitionEventTime &&
+      newEventType === transitionEventType;
+    transitionEventTime = newEventTime;
+    transitionEventType = newEventType;
   }
 }
 
@@ -115,12 +134,7 @@ export function clampBlockingTimers(finalTime: number): void {
   // If we had new updates come in while we were still rendering or committing, we don't want
   // those update times to create overlapping tracks in the performance timeline so we clamp
   // them to the end of the commit phase.
-  if (blockingUpdateTime >= 0 && blockingUpdateTime < finalTime) {
-    blockingUpdateTime = finalTime;
-  }
-  if (blockingEventTime >= 0 && blockingEventTime < finalTime) {
-    blockingEventTime = finalTime;
-  }
+  blockingClampTime = finalTime;
 }
 
 export function clampTransitionTimers(finalTime: number): void {
@@ -130,15 +144,7 @@ export function clampTransitionTimers(finalTime: number): void {
   // If we had new updates come in while we were still rendering or committing, we don't want
   // those update times to create overlapping tracks in the performance timeline so we clamp
   // them to the end of the commit phase.
-  if (transitionStartTime >= 0 && transitionStartTime < finalTime) {
-    transitionStartTime = finalTime;
-  }
-  if (transitionUpdateTime >= 0 && transitionUpdateTime < finalTime) {
-    transitionUpdateTime = finalTime;
-  }
-  if (transitionEventTime >= 0 && transitionEventTime < finalTime) {
-    transitionEventTime = finalTime;
-  }
+  transitionClampTime = finalTime;
 }
 
 export function pushNestedEffectDurations(): number {
diff --git a/packages/react-reconciler/src/__tests__/ReactFiberHostContext-test.internal.js b/packages/react-reconciler/src/__tests__/ReactFiberHostContext-test.internal.js
@@ -83,6 +83,7 @@ describe('ReactFiberHostContext', () => {
         }
         return DefaultEventPriority;
       },
+      trackSchedulerEvent: function () {},
       resolveEventType: function () {
         return null;
       },
diff --git a/packages/react-reconciler/src/forks/ReactFiberConfig.custom.js b/packages/react-reconciler/src/forks/ReactFiberConfig.custom.js
@@ -73,6 +73,7 @@ export const getInstanceFromScope = $$$config.getInstanceFromScope;
 export const setCurrentUpdatePriority = $$$config.setCurrentUpdatePriority;
 export const getCurrentUpdatePriority = $$$config.getCurrentUpdatePriority;
 export const resolveUpdatePriority = $$$config.resolveUpdatePriority;
+export const trackSchedulerEvent = $$$config.trackSchedulerEvent;
 export const resolveEventType = $$$config.resolveEventType;
 export const resolveEventTimeStamp = $$$config.resolveEventTimeStamp;
 export const shouldAttemptEagerTransition =
diff --git a/packages/react-test-renderer/src/ReactFiberConfigTestHost.js b/packages/react-test-renderer/src/ReactFiberConfigTestHost.js
@@ -224,10 +224,11 @@ export function resolveUpdatePriority(): EventPriority {
   }
   return DefaultEventPriority;
 }
+
+export function trackSchedulerEvent(): void {}
 export function resolveEventType(): null | string {
   return null;
 }
-
 export function resolveEventTimeStamp(): number {
   return -1.1;
 }
