[Fiber] Switch back to using performance.measure for trigger logs (#33659)
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: <img width="726" alt="Screenshot 2025-06-27 at 3 31 16 PM" src="https://github.com/user-attachments/assets/422341c8-bef6-4909-9403-933d76b71508" /> 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.
Sebastian Markbåge committed
Jul 2, 2025 at 16:10 UTC
508f7aa78ff53d058ee1151505efd5c4a4aefa01
1 file changed
+24
-32
packages/react-reconciler/src/ReactFiberPerformanceTrack.js
+24
-32
@@ -101,28 +101,22 @@ function logComponentTrigger(
101
trigger: string,
102
) {
103
if (supportsUserTiming) {
104
+ reusableComponentOptions.start = startTime;
105
+ reusableComponentOptions.end = endTime;
106
+ reusableComponentDevToolDetails.color = 'warning';
107
+ reusableComponentDevToolDetails.properties = null;
108
const debugTask = fiber._debugTask;
109
if (__DEV__ && debugTask) {
110
debugTask.run(
107
- console.timeStamp.bind(
108
- console,
111
+ // $FlowFixMe[method-unbinding]
112
+ performance.measure.bind(
113
+ performance,
114
trigger,
110
- startTime,
111
- endTime,
112
- COMPONENTS_TRACK,
113
- undefined,
114
- 'warning',
115
+ reusableComponentOptions,
116
),
117
);
118
} else {
118
- console.timeStamp(
119
- trigger,
120
- startTime,
121
- endTime,
122
- COMPONENTS_TRACK,
123
- undefined,
124
- 'warning',
125
- );
119
+ performance.measure(trigger, reusableComponentOptions);
120
}
121
}
122
}
@@ -578,7 +572,8 @@ export function logBlockingStart(
572
// If a blocking update was spawned within render or an effect, that's considered a cascading render.
573
// If you have a second blocking update within the same event, that suggests multiple flushSync or
574
// setState in a microtask which is also considered a cascade.
581
- if (eventTime > 0 && eventType !== null) {
575
+ const eventEndTime = updateTime > 0 ? updateTime : renderStartTime;
576
+ if (eventTime > 0 && eventType !== null && eventEndTime > eventTime) {
577
// Log the time from the event timeStamp until we called setState.
578
const color = eventIsRepeat ? 'secondary-light' : 'warning';
579
if (__DEV__ && debugTask) {
@@ -588,7 +583,7 @@ export function logBlockingStart(
583
console,
584
eventIsRepeat ? '' : 'Event: ' + eventType,
585
eventTime,
591
- updateTime > 0 ? updateTime : renderStartTime,
586
+ eventEndTime,
587
currentTrack,
588
LANES_TRACK_GROUP,
589
color,
@@ -598,14 +593,14 @@ export function logBlockingStart(
593
console.timeStamp(
594
eventIsRepeat ? '' : 'Event: ' + eventType,
595
eventTime,
601
- updateTime > 0 ? updateTime : renderStartTime,
596
+ eventEndTime,
597
currentTrack,
598
LANES_TRACK_GROUP,
599
color,
600
);
601
}
602
}
608
- if (updateTime > 0) {
603
+ if (updateTime > 0 && renderStartTime > updateTime) {
604
// Log the time from when we called setState until we started rendering.
605
const color = isSpawnedUpdate
606
? 'error'
@@ -658,15 +653,11 @@ export function logTransitionStart(
653
): void {
654
if (supportsUserTiming) {
655
currentTrack = 'Transition';
661
- if (eventTime > 0 && eventType !== null) {
656
+ const eventEndTime =
657
+ startTime > 0 ? startTime : updateTime > 0 ? updateTime : renderStartTime;
658
+ if (eventTime > 0 && eventEndTime > eventTime && eventType !== null) {
659
// Log the time from the event timeStamp until we started a transition.
660
const color = eventIsRepeat ? 'secondary-light' : 'warning';
664
- const endTime =
665
- startTime > 0
666
- ? startTime
667
- : updateTime > 0
668
- ? updateTime
669
- : renderStartTime;
661
if (__DEV__ && debugTask) {
662
debugTask.run(
663
// $FlowFixMe[method-unbinding]
@@ -674,7 +665,7 @@ export function logTransitionStart(
665
console,
666
eventIsRepeat ? '' : 'Event: ' + eventType,
667
eventTime,
677
- endTime,
668
+ eventEndTime,
669
currentTrack,
670
LANES_TRACK_GROUP,
671
color,
@@ -684,14 +675,15 @@ export function logTransitionStart(
675
console.timeStamp(
676
eventIsRepeat ? '' : 'Event: ' + eventType,
677
eventTime,
687
- endTime,
678
+ eventEndTime,
679
currentTrack,
680
LANES_TRACK_GROUP,
681
color,
682
);
683
}
684
}
694
- if (startTime > 0) {
685
+ const startEndTime = updateTime > 0 ? updateTime : renderStartTime;
686
+ if (startTime > 0 && startEndTime > startTime) {
687
// Log the time from when we started an async transition until we called setState or started rendering.
688
// TODO: Ideally this would use the debugTask of the startTransition call perhaps.
689
if (__DEV__ && debugTask) {
@@ -701,7 +693,7 @@ export function logTransitionStart(
693
console,
694
'Action',
695
startTime,
704
- updateTime > 0 ? updateTime : renderStartTime,
696
+ startEndTime,
697
currentTrack,
698
LANES_TRACK_GROUP,
699
'primary-dark',
@@ -711,14 +703,14 @@ export function logTransitionStart(
703
console.timeStamp(
704
'Action',
705
startTime,
714
- updateTime > 0 ? updateTime : renderStartTime,
706
+ startEndTime,
707
currentTrack,
708
LANES_TRACK_GROUP,
709
'primary-dark',
710
);
711
}
712
}
721
- if (updateTime > 0) {
713
+ if (updateTime > 0 && renderStartTime > updateTime) {
714
// Log the time from when we called setState until we started rendering.
715
if (__DEV__ && debugTask) {
716
debugTask.run(