From 508f7aa78ff53d058ee1151505efd5c4a4aefa01 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Sebastian=20Markb=C3=A5ge?= Date: Wed, 2 Jul 2025 16:10:52 -0400 Subject: [PATCH] [Fiber] Switch back to using performance.measure for trigger logs (#33659) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Stacked on #33658. Unfortunately `console.timeStamp` has the same bug that `performance.measure` used to have where equal start/end times stack in call order instead of reverse call-order. We rely on that in general so we should really switch back all. But there is one case in particular where we always add the same start/time and that's for the "triggers" - Mount/Unmount/Reconnect/Disconnect. Switching to `console.timeStamp` broke this because they now showed below the thing that mounted. After: Screenshot 2025-06-27 at 3 31 16 PM Also fixed a bug where clamped update times could end up logging zero width entries that stacked up on top of each other causing a two row scheduler lane which should always be one row. --- .../src/ReactFiberPerformanceTrack.js | 56 ++++++++----------- 1 file changed, 24 insertions(+), 32 deletions(-) diff --git a/packages/react-reconciler/src/ReactFiberPerformanceTrack.js b/packages/react-reconciler/src/ReactFiberPerformanceTrack.js index bae0db56d6..faec8c6341 100644 --- a/packages/react-reconciler/src/ReactFiberPerformanceTrack.js +++ b/packages/react-reconciler/src/ReactFiberPerformanceTrack.js @@ -101,28 +101,22 @@ function logComponentTrigger( trigger: string, ) { if (supportsUserTiming) { + reusableComponentOptions.start = startTime; + reusableComponentOptions.end = endTime; + reusableComponentDevToolDetails.color = 'warning'; + reusableComponentDevToolDetails.properties = null; const debugTask = fiber._debugTask; if (__DEV__ && debugTask) { debugTask.run( - console.timeStamp.bind( - console, + // $FlowFixMe[method-unbinding] + performance.measure.bind( + performance, trigger, - startTime, - endTime, - COMPONENTS_TRACK, - undefined, - 'warning', + reusableComponentOptions, ), ); } else { - console.timeStamp( - trigger, - startTime, - endTime, - COMPONENTS_TRACK, - undefined, - 'warning', - ); + performance.measure(trigger, reusableComponentOptions); } } } @@ -578,7 +572,8 @@ export function logBlockingStart( // 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. - if (eventTime > 0 && eventType !== null) { + const eventEndTime = updateTime > 0 ? updateTime : renderStartTime; + if (eventTime > 0 && eventType !== null && eventEndTime > eventTime) { // Log the time from the event timeStamp until we called setState. const color = eventIsRepeat ? 'secondary-light' : 'warning'; if (__DEV__ && debugTask) { @@ -588,7 +583,7 @@ export function logBlockingStart( console, eventIsRepeat ? '' : 'Event: ' + eventType, eventTime, - updateTime > 0 ? updateTime : renderStartTime, + eventEndTime, currentTrack, LANES_TRACK_GROUP, color, @@ -598,14 +593,14 @@ export function logBlockingStart( console.timeStamp( eventIsRepeat ? '' : 'Event: ' + eventType, eventTime, - updateTime > 0 ? updateTime : renderStartTime, + eventEndTime, currentTrack, LANES_TRACK_GROUP, color, ); } } - if (updateTime > 0) { + if (updateTime > 0 && renderStartTime > updateTime) { // Log the time from when we called setState until we started rendering. const color = isSpawnedUpdate ? 'error' @@ -658,15 +653,11 @@ export function logTransitionStart( ): void { if (supportsUserTiming) { currentTrack = 'Transition'; - if (eventTime > 0 && eventType !== null) { + const eventEndTime = + startTime > 0 ? startTime : updateTime > 0 ? updateTime : renderStartTime; + if (eventTime > 0 && eventEndTime > eventTime && eventType !== null) { // Log the time from the event timeStamp until we started a transition. const color = eventIsRepeat ? 'secondary-light' : 'warning'; - const endTime = - startTime > 0 - ? startTime - : updateTime > 0 - ? updateTime - : renderStartTime; if (__DEV__ && debugTask) { debugTask.run( // $FlowFixMe[method-unbinding] @@ -674,7 +665,7 @@ export function logTransitionStart( console, eventIsRepeat ? '' : 'Event: ' + eventType, eventTime, - endTime, + eventEndTime, currentTrack, LANES_TRACK_GROUP, color, @@ -684,14 +675,15 @@ export function logTransitionStart( console.timeStamp( eventIsRepeat ? '' : 'Event: ' + eventType, eventTime, - endTime, + eventEndTime, currentTrack, LANES_TRACK_GROUP, color, ); } } - if (startTime > 0) { + const startEndTime = updateTime > 0 ? updateTime : renderStartTime; + if (startTime > 0 && startEndTime > 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) { @@ -701,7 +693,7 @@ export function logTransitionStart( console, 'Action', startTime, - updateTime > 0 ? updateTime : renderStartTime, + startEndTime, currentTrack, LANES_TRACK_GROUP, 'primary-dark', @@ -711,14 +703,14 @@ export function logTransitionStart( console.timeStamp( 'Action', startTime, - updateTime > 0 ? updateTime : renderStartTime, + startEndTime, currentTrack, LANES_TRACK_GROUP, 'primary-dark', ); } } - if (updateTime > 0) { + if (updateTime > 0 && renderStartTime > updateTime) { // Log the time from when we called setState until we started rendering. if (__DEV__ && debugTask) { debugTask.run(