Repository: facebook/react
Pull request: Ensure Performance Track are Clamped and Don't overlap

This simplifies the logic for clamping the start times of various phases. Instead of checking in multiple places I ensure we compute a value for each phase that is then clamped to the next phase so they don't overlap. If they're zero they're not printed.

I also added a name for all the anonymous labels. Those are mainly fillers for sync work that should be quick but it helps debugging if we can name them.

Finally the real fix is to update the clamp time which previously could lead to overlapping entries for consecutive updates when a previous update never finalized before the next update.

Changed files:
filename: packages/react-reconciler/src/ReactFiberPerformanceTrack.js
patch: @@ -636,38 +636,52 @@ export function logBlockingStart(
 ): void {
   if (supportsUserTiming) {
     currentTrack = 'Blocking';
+    // Clamp start times
+    if (updateTime > 0) {
+      if (updateTime > renderStartTime) {
+        updateTime = renderStartTime;
+      }
+    } else {
+      updateTime = renderStartTime;
+    }
+    if (eventTime > 0) {
+      if (eventTime > updateTime) {
+        eventTime = updateTime;
+      }
+    } else {
+      eventTime = updateTime;
+    }
     // If a blocking update was spawned within render or an effect, that's considered a cascading render.
     // If you have a second blocking update within the same event, that suggests multiple flushSync or
     // setState in a microtask which is also considered a cascade.
-    const eventEndTime = updateTime > 0 ? updateTime : renderStartTime;
-    if (eventTime > 0 && eventType !== null && eventEndTime > eventTime) {
+    if (eventType !== null && updateTime > eventTime) {
       // Log the time from the event timeStamp until we called setState.
       const color = eventIsRepeat ? 'secondary-light' : 'warning';
       if (__DEV__ && debugTask) {
         debugTask.run(
           // $FlowFixMe[method-unbinding]
           console.timeStamp.bind(
             console,
-            eventIsRepeat ? '' : 'Event: ' + eventType,
+            eventIsRepeat ? 'Consecutive' : 'Event: ' + eventType,
             eventTime,
-            eventEndTime,
+            updateTime,
             currentTrack,
             LANES_TRACK_GROUP,
             color,
           ),
         );
       } else {
         console.timeStamp(
-          eventIsRepeat ? '' : 'Event: ' + eventType,
+          eventIsRepeat ? 'Consecutive' : 'Event: ' + eventType,
           eventTime,
-          eventEndTime,
+          updateTime,
           currentTrack,
           LANES_TRACK_GROUP,
           color,
         );
       }
     }
-    if (updateTime > 0 && renderStartTime > updateTime) {
+    if (renderStartTime > updateTime) {
       // Log the time from when we called setState until we started rendering.
       const color = isSpawnedUpdate
         ? 'error'
@@ -739,36 +753,56 @@ export function logTransitionStart(
 ): void {
   if (supportsUserTiming) {
     currentTrack = 'Transition';
-    const eventEndTime =
-      startTime > 0 ? startTime : updateTime > 0 ? updateTime : renderStartTime;
-    if (eventTime > 0 && eventEndTime > eventTime && eventType !== null) {
+    // Clamp start times
+    if (updateTime > 0) {
+      if (updateTime > renderStartTime) {
+        updateTime = renderStartTime;
+      }
+    } else {
+      updateTime = renderStartTime;
+    }
+    if (startTime > 0) {
+      if (startTime > updateTime) {
+        startTime = updateTime;
+      }
+    } else {
+      startTime = updateTime;
+    }
+    if (eventTime > 0) {
+      if (eventTime > startTime) {
+        eventTime = startTime;
+      }
+    } else {
+      eventTime = startTime;
+    }
+
+    if (startTime > eventTime && eventType !== null) {
       // Log the time from the event timeStamp until we started a transition.
       const color = eventIsRepeat ? 'secondary-light' : 'warning';
       if (__DEV__ && debugTask) {
         debugTask.run(
           console.timeStamp.bind(
             console,
-            eventIsRepeat ? '' : 'Event: ' + eventType,
+            eventIsRepeat ? 'Consecutive' : 'Event: ' + eventType,
             eventTime,
-            eventEndTime,
+            startTime,
             currentTrack,
             LANES_TRACK_GROUP,
             color,
           ),
         );
       } else {
         console.timeStamp(
-          eventIsRepeat ? '' : 'Event: ' + eventType,
+          eventIsRepeat ? 'Consecutive' : 'Event: ' + eventType,
           eventTime,
-          eventEndTime,
+          startTime,
           currentTrack,
           LANES_TRACK_GROUP,
           color,
         );
       }
     }
-    const startEndTime = updateTime > 0 ? updateTime : renderStartTime;
-    if (startTime > 0 && startEndTime > startTime) {
+    if (updateTime > startTime) {
       // Log the time from when we started an async transition until we called setState or started rendering.
       // TODO: Ideally this would use the debugTask of the startTransition call perhaps.
       if (__DEV__ && debugTask) {
@@ -778,7 +812,7 @@ export function logTransitionStart(
             console,
             'Action',
             startTime,
-            startEndTime,
+            updateTime,
             currentTrack,
             LANES_TRACK_GROUP,
             'primary-dark',
@@ -788,14 +822,14 @@ export function logTransitionStart(
         console.timeStamp(
           'Action',
           startTime,
-          startEndTime,
+          updateTime,
           currentTrack,
           LANES_TRACK_GROUP,
           'primary-dark',
         );
       }
     }
-    if (updateTime > 0 && renderStartTime > updateTime) {
+    if (renderStartTime > updateTime) {
       // Log the time from when we called setState until we started rendering.
       const label = isPingedUpdate
         ? 'Promise Resolved'
@@ -1337,7 +1371,7 @@ export function logPaintYieldPhase(
         // $FlowFixMe[method-unbinding]
         console.timeStamp.bind(
           console,
-          delayedUntilPaint ? 'Waiting for Paint' : '',
+          delayedUntilPaint ? 'Waiting for Paint' : 'Waiting',
           startTime,
           endTime,
           currentTrack,
@@ -1347,7 +1381,7 @@ export function logPaintYieldPhase(
       );
     } else {
       console.timeStamp(
-        delayedUntilPaint ? 'Waiting for Paint' : '',
+        delayedUntilPaint ? 'Waiting for Paint' : 'Waiting',
         startTime,
         endTime,
         currentTrack,

filename: packages/react-reconciler/src/ReactProfilerTimer.js
patch: @@ -246,6 +246,7 @@ export function clearBlockingTimers(): void {
   blockingUpdateComponentName = null;
   blockingSuspendedTime = -1.1;
   blockingEventIsRepeat = true;
+  blockingClampTime = now();
 }
 
 export function startAsyncTransitionTimer(): void {
@@ -282,6 +283,7 @@ export function clearTransitionTimers(): void {
   transitionUpdateType = 0;
   transitionSuspendedTime = -1.1;
   transitionEventIsRepeat = true;
+  transitionClampTime = now();
 }
 
 export function clampBlockingTimers(finalTime: number): void {

filename: packages/react/src/__tests__/ReactProfiler-test.internal.js
patch: @@ -179,6 +179,7 @@ describe(`onRender`, () => {
         'read current time',
         'read current time',
         'read current time',
+        'read current time',
       ]);
     } else {
       assertLog([