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.
This commit is contained in:
Sebastian Markbåge
2025-09-17 10:52:02 -04:00
committed by GitHub
parent 27b4076ab0
commit e3c9656d20
3 changed files with 58 additions and 21 deletions
+55 -21
View File
@@ -636,11 +636,25 @@ 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) {
@@ -648,9 +662,9 @@ export function logBlockingStart(
// $FlowFixMe[method-unbinding]
console.timeStamp.bind(
console,
eventIsRepeat ? '' : 'Event: ' + eventType,
eventIsRepeat ? 'Consecutive' : 'Event: ' + eventType,
eventTime,
eventEndTime,
updateTime,
currentTrack,
LANES_TRACK_GROUP,
color,
@@ -658,16 +672,16 @@ export function logBlockingStart(
);
} 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,18 +753,39 @@ 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,
@@ -758,17 +793,16 @@ export function logTransitionStart(
);
} 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,
+2
View File
@@ -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 {
@@ -179,6 +179,7 @@ describe(`onRender`, () => {
'read current time',
'read current time',
'read current time',
'read current time',
]);
} else {
assertLog([