Skip to content

Commit e3c9656

Browse files
authored
Ensure Performance Track are Clamped and Don't overlap (#34509)
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.
1 parent 27b4076 commit e3c9656

File tree

3 files changed

+58
-21
lines changed

3 files changed

+58
-21
lines changed

packages/react-reconciler/src/ReactFiberPerformanceTrack.js

Lines changed: 55 additions & 21 deletions
Original file line numberDiff line numberDiff line change
@@ -636,38 +636,52 @@ export function logBlockingStart(
636636
): void {
637637
if (supportsUserTiming) {
638638
currentTrack = 'Blocking';
639+
// Clamp start times
640+
if (updateTime > 0) {
641+
if (updateTime > renderStartTime) {
642+
updateTime = renderStartTime;
643+
}
644+
} else {
645+
updateTime = renderStartTime;
646+
}
647+
if (eventTime > 0) {
648+
if (eventTime > updateTime) {
649+
eventTime = updateTime;
650+
}
651+
} else {
652+
eventTime = updateTime;
653+
}
639654
// If a blocking update was spawned within render or an effect, that's considered a cascading render.
640655
// If you have a second blocking update within the same event, that suggests multiple flushSync or
641656
// setState in a microtask which is also considered a cascade.
642-
const eventEndTime = updateTime > 0 ? updateTime : renderStartTime;
643-
if (eventTime > 0 && eventType !== null && eventEndTime > eventTime) {
657+
if (eventType !== null && updateTime > eventTime) {
644658
// Log the time from the event timeStamp until we called setState.
645659
const color = eventIsRepeat ? 'secondary-light' : 'warning';
646660
if (__DEV__ && debugTask) {
647661
debugTask.run(
648662
// $FlowFixMe[method-unbinding]
649663
console.timeStamp.bind(
650664
console,
651-
eventIsRepeat ? '' : 'Event: ' + eventType,
665+
eventIsRepeat ? 'Consecutive' : 'Event: ' + eventType,
652666
eventTime,
653-
eventEndTime,
667+
updateTime,
654668
currentTrack,
655669
LANES_TRACK_GROUP,
656670
color,
657671
),
658672
);
659673
} else {
660674
console.timeStamp(
661-
eventIsRepeat ? '' : 'Event: ' + eventType,
675+
eventIsRepeat ? 'Consecutive' : 'Event: ' + eventType,
662676
eventTime,
663-
eventEndTime,
677+
updateTime,
664678
currentTrack,
665679
LANES_TRACK_GROUP,
666680
color,
667681
);
668682
}
669683
}
670-
if (updateTime > 0 && renderStartTime > updateTime) {
684+
if (renderStartTime > updateTime) {
671685
// Log the time from when we called setState until we started rendering.
672686
const color = isSpawnedUpdate
673687
? 'error'
@@ -739,36 +753,56 @@ export function logTransitionStart(
739753
): void {
740754
if (supportsUserTiming) {
741755
currentTrack = 'Transition';
742-
const eventEndTime =
743-
startTime > 0 ? startTime : updateTime > 0 ? updateTime : renderStartTime;
744-
if (eventTime > 0 && eventEndTime > eventTime && eventType !== null) {
756+
// Clamp start times
757+
if (updateTime > 0) {
758+
if (updateTime > renderStartTime) {
759+
updateTime = renderStartTime;
760+
}
761+
} else {
762+
updateTime = renderStartTime;
763+
}
764+
if (startTime > 0) {
765+
if (startTime > updateTime) {
766+
startTime = updateTime;
767+
}
768+
} else {
769+
startTime = updateTime;
770+
}
771+
if (eventTime > 0) {
772+
if (eventTime > startTime) {
773+
eventTime = startTime;
774+
}
775+
} else {
776+
eventTime = startTime;
777+
}
778+
779+
if (startTime > eventTime && eventType !== null) {
745780
// Log the time from the event timeStamp until we started a transition.
746781
const color = eventIsRepeat ? 'secondary-light' : 'warning';
747782
if (__DEV__ && debugTask) {
748783
debugTask.run(
749784
console.timeStamp.bind(
750785
console,
751-
eventIsRepeat ? '' : 'Event: ' + eventType,
786+
eventIsRepeat ? 'Consecutive' : 'Event: ' + eventType,
752787
eventTime,
753-
eventEndTime,
788+
startTime,
754789
currentTrack,
755790
LANES_TRACK_GROUP,
756791
color,
757792
),
758793
);
759794
} else {
760795
console.timeStamp(
761-
eventIsRepeat ? '' : 'Event: ' + eventType,
796+
eventIsRepeat ? 'Consecutive' : 'Event: ' + eventType,
762797
eventTime,
763-
eventEndTime,
798+
startTime,
764799
currentTrack,
765800
LANES_TRACK_GROUP,
766801
color,
767802
);
768803
}
769804
}
770-
const startEndTime = updateTime > 0 ? updateTime : renderStartTime;
771-
if (startTime > 0 && startEndTime > startTime) {
805+
if (updateTime > startTime) {
772806
// Log the time from when we started an async transition until we called setState or started rendering.
773807
// TODO: Ideally this would use the debugTask of the startTransition call perhaps.
774808
if (__DEV__ && debugTask) {
@@ -778,7 +812,7 @@ export function logTransitionStart(
778812
console,
779813
'Action',
780814
startTime,
781-
startEndTime,
815+
updateTime,
782816
currentTrack,
783817
LANES_TRACK_GROUP,
784818
'primary-dark',
@@ -788,14 +822,14 @@ export function logTransitionStart(
788822
console.timeStamp(
789823
'Action',
790824
startTime,
791-
startEndTime,
825+
updateTime,
792826
currentTrack,
793827
LANES_TRACK_GROUP,
794828
'primary-dark',
795829
);
796830
}
797831
}
798-
if (updateTime > 0 && renderStartTime > updateTime) {
832+
if (renderStartTime > updateTime) {
799833
// Log the time from when we called setState until we started rendering.
800834
const label = isPingedUpdate
801835
? 'Promise Resolved'
@@ -1337,7 +1371,7 @@ export function logPaintYieldPhase(
13371371
// $FlowFixMe[method-unbinding]
13381372
console.timeStamp.bind(
13391373
console,
1340-
delayedUntilPaint ? 'Waiting for Paint' : '',
1374+
delayedUntilPaint ? 'Waiting for Paint' : 'Waiting',
13411375
startTime,
13421376
endTime,
13431377
currentTrack,
@@ -1347,7 +1381,7 @@ export function logPaintYieldPhase(
13471381
);
13481382
} else {
13491383
console.timeStamp(
1350-
delayedUntilPaint ? 'Waiting for Paint' : '',
1384+
delayedUntilPaint ? 'Waiting for Paint' : 'Waiting',
13511385
startTime,
13521386
endTime,
13531387
currentTrack,

packages/react-reconciler/src/ReactProfilerTimer.js

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -246,6 +246,7 @@ export function clearBlockingTimers(): void {
246246
blockingUpdateComponentName = null;
247247
blockingSuspendedTime = -1.1;
248248
blockingEventIsRepeat = true;
249+
blockingClampTime = now();
249250
}
250251

251252
export function startAsyncTransitionTimer(): void {
@@ -282,6 +283,7 @@ export function clearTransitionTimers(): void {
282283
transitionUpdateType = 0;
283284
transitionSuspendedTime = -1.1;
284285
transitionEventIsRepeat = true;
286+
transitionClampTime = now();
285287
}
286288

287289
export function clampBlockingTimers(finalTime: number): void {

packages/react/src/__tests__/ReactProfiler-test.internal.js

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -179,6 +179,7 @@ describe(`onRender`, () => {
179179
'read current time',
180180
'read current time',
181181
'read current time',
182+
'read current time',
182183
]);
183184
} else {
184185
assertLog([

0 commit comments

Comments
 (0)