OSSForks/react
1
0
Fork 0
mirror of https://github.com/zebrajr/react.git synced 2025-12-06 12:20:20 +01:00
Code Issues Actions 5 Packages Projects Releases Wiki Activity

Run Component Track Logs in the console.createTask() of the Fiber (#32809)

Browse Source 
Stacked on #32736.

That way you can find the owner stack of each component that rerendered
for context.

In addition to the JSX callsite tasks that we already track, I also
added tracking of the first `setState` call before rendering.

We then run the "Update" entries in that task. That way you can find the
callsite of the first setState and therefore the "cause" of a render
starting by selecting the "Update" track.

Unfortunately this is blocked on bugs in Chrome that makes it so that
these stacks are not reliable in the Performance tab. It basically just
doesn't work.
This commit is contained in:
Sebastian Markbåge 2025-04-29 22:17:17 -04:00 committed by GitHub
parent cd4e4d7599
commit 62960c67c8
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
7 changed files with 358 additions and 113 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

64
packages/react-client/src/ReactFlightPerformanceTrack.js vendored
View File

@ -78,14 +78,30 @@ export function logComponentRender(
: 'error';
const entryName =
isPrimaryEnv || env === undefined ? name : name + ' [' + env + ']';
console.timeStamp(
entryName,
startTime < 0 ? 0 : startTime,
childrenEndTime,
trackNames[trackIdx],
COMPONENTS_TRACK,
color,
);
const debugTask = componentInfo.debugTask;
if (__DEV__ && debugTask) {
debugTask.run(
// $FlowFixMe[method-unbinding]
console.timeStamp.bind(
console,
entryName,
startTime < 0 ? 0 : startTime,
childrenEndTime,
trackNames[trackIdx],
COMPONENTS_TRACK,
color,
),
);
} else {
console.timeStamp(
entryName,
startTime < 0 ? 0 : startTime,
childrenEndTime,
trackNames[trackIdx],
COMPONENTS_TRACK,
color,
);
}
}
}
@ -154,13 +170,29 @@ export function logDedupedComponentRender(
if (supportsUserTiming && endTime >= 0 && trackIdx < 10) {
const name = componentInfo.name;
const entryName = name + ' [deduped]';
console.timeStamp(
entryName,
startTime < 0 ? 0 : startTime,
endTime,
trackNames[trackIdx],
COMPONENTS_TRACK,
'tertiary-light',
);
const debugTask = componentInfo.debugTask;
if (__DEV__ && debugTask) {
debugTask.run(
// $FlowFixMe[method-unbinding]
console.timeStamp.bind(
console,
entryName,
startTime < 0 ? 0 : startTime,
endTime,
trackNames[trackIdx],
COMPONENTS_TRACK,
'tertiary-light',
),
);
} else {
console.timeStamp(
entryName,
startTime < 0 ? 0 : startTime,
endTime,
trackNames[trackIdx],
COMPONENTS_TRACK,
'tertiary-light',
);
}
}
}

6
packages/react-reconciler/src/ReactFiberClassComponent.js vendored
View File

@ -180,7 +180,7 @@ const classComponentUpdater = {
const root = enqueueUpdate(fiber, update, lane);
if (root !== null) {
startUpdateTimerByLane(lane);
startUpdateTimerByLane(lane, 'this.setState()');
scheduleUpdateOnFiber(root, fiber, lane);
entangleTransitions(root, fiber, lane);
}
@ -206,7 +206,7 @@ const classComponentUpdater = {
const root = enqueueUpdate(fiber, update, lane);
if (root !== null) {
startUpdateTimerByLane(lane);
startUpdateTimerByLane(lane, 'this.replaceState()');
scheduleUpdateOnFiber(root, fiber, lane);
entangleTransitions(root, fiber, lane);
}
@ -232,7 +232,7 @@ const classComponentUpdater = {
const root = enqueueUpdate(fiber, update, lane);
if (root !== null) {
startUpdateTimerByLane(lane);
startUpdateTimerByLane(lane, 'this.forceUpdate()');
scheduleUpdateOnFiber(root, fiber, lane);
entangleTransitions(root, fiber, lane);
}

11
packages/react-reconciler/src/ReactFiberHooks.js vendored
View File

@ -1847,6 +1847,8 @@ function updateStoreInstance<T>(
// snapsho and getSnapshot values to bail out. We need to check one more time.
if (checkIfSnapshotChanged(inst)) {
// Force a re-render.
// We intentionally don't log update times and stacks here because this
// was not an external trigger but rather an internal one.
forceStoreRerender(fiber);
}
}
@ -1861,6 +1863,7 @@ function subscribeToStore<T>(
// read from the store.
if (checkIfSnapshotChanged(inst)) {
// Force a re-render.
startUpdateTimerByLane(SyncLane, 'updateSyncExternalStore()');
forceStoreRerender(fiber);
}
};
@ -3503,7 +3506,7 @@ function refreshCache<T>(fiber: Fiber, seedKey: ?() => T, seedValue: T): void {
const refreshUpdate = createLegacyQueueUpdate(lane);
const root = enqueueLegacyQueueUpdate(provider, refreshUpdate, lane);
if (root !== null) {
startUpdateTimerByLane(lane);
startUpdateTimerByLane(lane, 'refresh()');
scheduleUpdateOnFiber(root, provider, lane);
entangleLegacyQueueTransitions(root, provider, lane);
}
@ -3572,7 +3575,7 @@ function dispatchReducerAction<S, A>(
} else {
const root = enqueueConcurrentHookUpdate(fiber, queue, update, lane);
if (root !== null) {
startUpdateTimerByLane(lane);
startUpdateTimerByLane(lane, 'dispatch()');
scheduleUpdateOnFiber(root, fiber, lane);
entangleTransitionUpdate(root, queue, lane);
}
@ -3606,7 +3609,7 @@ function dispatchSetState<S, A>(
lane,
);
if (didScheduleUpdate) {
startUpdateTimerByLane(lane);
startUpdateTimerByLane(lane, 'setState()');
}
markUpdateInDevTools(fiber, lane, action);
}
@ -3768,7 +3771,7 @@ function dispatchOptimisticSetState<S, A>(
// will never be attempted before the optimistic update. This currently
// holds because the optimistic update is always synchronous. If we ever
// change that, we'll need to account for this.
startUpdateTimerByLane(lane);
startUpdateTimerByLane(lane, 'setOptimistic()');
scheduleUpdateOnFiber(root, fiber, lane);
// Optimistic updates are always synchronous, so we don't need to call
// entangleTransitionUpdate here.

368
packages/react-reconciler/src/ReactFiberPerformanceTrack.js vendored
View File

@ -103,14 +103,29 @@ function logComponentTrigger(
trigger: string,
) {
if (supportsUserTiming) {
console.timeStamp(
trigger,
startTime,
endTime,
COMPONENTS_TRACK,
undefined,
'warning',
);
const debugTask = fiber._debugTask;
if (__DEV__ && debugTask) {
debugTask.run(
console.timeStamp.bind(
console,
trigger,
startTime,
endTime,
COMPONENTS_TRACK,
undefined,
'warning',
),
);
} else {
console.timeStamp(
trigger,
startTime,
endTime,
COMPONENTS_TRACK,
undefined,
'warning',
);
}
}
}
@ -178,14 +193,30 @@ export function logComponentRender(
? 'tertiary-dark'
: 'primary-dark'
: 'error';
console.timeStamp(
name,
startTime,
endTime,
COMPONENTS_TRACK,
undefined,
color,
);
const debugTask = fiber._debugTask;
if (__DEV__ && debugTask) {
debugTask.run(
// $FlowFixMe[method-unbinding]
console.timeStamp.bind(
console,
name,
startTime,
endTime,
COMPONENTS_TRACK,
undefined,
color,
),
);
} else {
console.timeStamp(
name,
startTime,
endTime,
COMPONENTS_TRACK,
undefined,
color,
);
}
}
}
@ -207,9 +238,18 @@ export function logComponentErrored(
// $FlowFixMe[method-unbinding]
typeof performance.measure === 'function'
) {
let debugTask: ?ConsoleTask = null;
const properties = [];
for (let i = 0; i < errors.length; i++) {
const capturedValue = errors[i];
if (debugTask == null && capturedValue.source !== null) {
// If the captured value has a source Fiber, use its debugTask for
// the stack instead of the error boundary's stack. So you can find
// which component errored since we don't show the errored render tree.
// TODO: Ideally we should instead, store the failed fibers and log the
// whole subtree including the component that errored.
debugTask = capturedValue.source._debugTask;
}
const error = capturedValue.value;
const message =
typeof error === 'object' &&
@ -221,7 +261,12 @@ export function logComponentErrored(
String(error);
properties.push(['Error', message]);
}
performance.measure(name, {
if (debugTask == null) {
// If the captured values don't have a debug task, fallback to the
// error boundary itself.
debugTask = fiber._debugTask;
}
const options = {
start: startTime,
end: endTime,
detail: {
@ -235,7 +280,15 @@ export function logComponentErrored(
properties,
},
},
});
};
if (__DEV__ && debugTask) {
debugTask.run(
// $FlowFixMe[method-unbinding]
performance.measure.bind(performance, name, options),
);
} else {
performance.measure(name, options);
}
} else {
console.timeStamp(
name,
@ -281,7 +334,7 @@ function logComponentEffectErrored(
String(error);
properties.push(['Error', message]);
}
performance.measure(name, {
const options = {
start: startTime,
end: endTime,
detail: {
@ -292,7 +345,16 @@ function logComponentEffectErrored(
properties,
},
},
});
};
const debugTask = fiber._debugTask;
if (debugTask) {
debugTask.run(
// $FlowFixMe[method-unbinding]
performance.measure.bind(performance, name, options),
);
} else {
performance.measure(name, options);
}
} else {
console.timeStamp(
name,
@ -331,14 +393,30 @@ export function logComponentEffect(
: selfTime < 500
? 'secondary-dark'
: 'error';
console.timeStamp(
name,
startTime,
endTime,
COMPONENTS_TRACK,
undefined,
color,
);
const debugTask = fiber._debugTask;
if (__DEV__ && debugTask) {
debugTask.run(
// $FlowFixMe[method-unbinding]
console.timeStamp.bind(
console,
name,
startTime,
endTime,
COMPONENTS_TRACK,
undefined,
color,
),
);
} else {
console.timeStamp(
name,
startTime,
endTime,
COMPONENTS_TRACK,
undefined,
color,
);
}
}
}
@ -379,14 +457,30 @@ export function logSuspendedYieldTime(
suspendedFiber: Fiber,
): void {
if (supportsUserTiming) {
console.timeStamp(
'Suspended',
startTime,
endTime,
COMPONENTS_TRACK,
undefined,
'primary-light',
);
const debugTask = suspendedFiber._debugTask;
if (__DEV__ && debugTask) {
debugTask.run(
// $FlowFixMe[method-unbinding]
console.timeStamp.bind(
console,
'Suspended',
startTime,
endTime,
COMPONENTS_TRACK,
undefined,
'primary-light',
),
);
} else {
console.timeStamp(
'Suspended',
startTime,
endTime,
COMPONENTS_TRACK,
undefined,
'primary-light',
);
}
}
}
@ -396,14 +490,30 @@ export function logActionYieldTime(
suspendedFiber: Fiber,
): void {
if (supportsUserTiming) {
console.timeStamp(
'Action',
startTime,
endTime,
COMPONENTS_TRACK,
undefined,
'primary-light',
);
const debugTask = suspendedFiber._debugTask;
if (__DEV__ && debugTask) {
debugTask.run(
// $FlowFixMe[method-unbinding]
console.timeStamp.bind(
console,
'Action',
startTime,
endTime,
COMPONENTS_TRACK,
undefined,
'primary-light',
),
);
} else {
console.timeStamp(
'Action',
startTime,
endTime,
COMPONENTS_TRACK,
undefined,
'primary-light',
);
}
}
}
@ -415,6 +525,7 @@ export function logBlockingStart(
isSpawnedUpdate: boolean,
renderStartTime: number,
lanes: Lanes,
debugTask: null | ConsoleTask, // DEV-only
): void {
if (supportsUserTiming) {
currentTrack = 'Blocking';
@ -424,14 +535,29 @@ export function logBlockingStart(
if (eventTime > 0 && eventType !== null) {
// Log the time from the event timeStamp until we called setState.
const color = eventIsRepeat ? 'secondary-light' : 'warning';
console.timeStamp(
eventIsRepeat ? '' : 'Event: ' + eventType,
eventTime,
updateTime > 0 ? updateTime : renderStartTime,
currentTrack,
LANES_TRACK_GROUP,
color,
);
if (__DEV__ && debugTask) {
debugTask.run(
// $FlowFixMe[method-unbinding]
console.timeStamp.bind(
console,
eventIsRepeat ? '' : 'Event: ' + eventType,
eventTime,
updateTime > 0 ? updateTime : renderStartTime,
currentTrack,
LANES_TRACK_GROUP,
color,
),
);
} else {
console.timeStamp(
eventIsRepeat ? '' : 'Event: ' + eventType,
eventTime,
updateTime > 0 ? updateTime : renderStartTime,
currentTrack,
LANES_TRACK_GROUP,
color,
);
}
}
if (updateTime > 0) {
// Log the time from when we called setState until we started rendering.
@ -440,18 +566,37 @@ export function logBlockingStart(
: includesOnlyHydrationOrOffscreenLanes(lanes)
? 'tertiary-light'
: 'primary-light';
console.timeStamp(
isSpawnedUpdate
? 'Cascading Update'
: renderStartTime - updateTime > 5
? 'Update Blocked'
: 'Update',
updateTime,
renderStartTime,
currentTrack,
LANES_TRACK_GROUP,
color,
);
if (__DEV__ && debugTask) {
debugTask.run(
// $FlowFixMe[method-unbinding]
console.timeStamp.bind(
console,
isSpawnedUpdate
? 'Cascading Update'
: renderStartTime - updateTime > 5
? 'Update Blocked'
: 'Update',
updateTime,
renderStartTime,
currentTrack,
LANES_TRACK_GROUP,
color,
),
);
} else {
console.timeStamp(
isSpawnedUpdate
? 'Cascading Update'
: renderStartTime - updateTime > 5
? 'Update Blocked'
: 'Update',
updateTime,
renderStartTime,
currentTrack,
LANES_TRACK_GROUP,
color,
);
}
}
}
}
@ -463,6 +608,7 @@ export function logTransitionStart(
eventType: null | string,
eventIsRepeat: boolean,
renderStartTime: number,
debugTask: null | ConsoleTask, // DEV-only
): void {
if (supportsUserTiming) {
currentTrack = 'Transition';
@ -475,36 +621,82 @@ export function logTransitionStart(
: updateTime > 0
? updateTime
: renderStartTime;
console.timeStamp(
eventIsRepeat ? '' : 'Event: ' + eventType,
eventTime,
endTime,
currentTrack,
LANES_TRACK_GROUP,
color,
);
if (__DEV__ && debugTask) {
debugTask.run(
// $FlowFixMe[method-unbinding]
console.timeStamp.bind(
console,
eventIsRepeat ? '' : 'Event: ' + eventType,
eventTime,
endTime,
currentTrack,
LANES_TRACK_GROUP,
color,
),
);
} else {
console.timeStamp(
eventIsRepeat ? '' : 'Event: ' + eventType,
eventTime,
endTime,
currentTrack,
LANES_TRACK_GROUP,
color,
);
}
}
if (startTime > 0) {
// Log the time from when we started an async transition until we called setState or started rendering.
console.timeStamp(
'Action',
startTime,
updateTime > 0 ? updateTime : renderStartTime,
currentTrack,
LANES_TRACK_GROUP,
'primary-dark',
);
// TODO: Ideally this would use the debugTask of the startTransition call perhaps.
if (__DEV__ && debugTask) {
debugTask.run(
// $FlowFixMe[method-unbinding]
console.timeStamp.bind(
console,
'Action',
startTime,
updateTime > 0 ? updateTime : renderStartTime,
currentTrack,
LANES_TRACK_GROUP,
'primary-dark',
),
);
} else {
console.timeStamp(
'Action',
startTime,
updateTime > 0 ? updateTime : renderStartTime,
currentTrack,
LANES_TRACK_GROUP,
'primary-dark',
);
}
}
if (updateTime > 0) {
// Log the time from when we called setState until we started rendering.
console.timeStamp(
renderStartTime - updateTime > 5 ? 'Update Blocked' : 'Update',
updateTime,
renderStartTime,
currentTrack,
LANES_TRACK_GROUP,
'primary-light',
);
if (__DEV__ && debugTask) {
debugTask.run(
// $FlowFixMe[method-unbinding]
console.timeStamp.bind(
console,
renderStartTime - updateTime > 5 ? 'Update Blocked' : 'Update',
updateTime,
renderStartTime,
currentTrack,
LANES_TRACK_GROUP,
'primary-light',
),
);
} else {
console.timeStamp(
renderStartTime - updateTime > 5 ? 'Update Blocked' : 'Update',
updateTime,
renderStartTime,
currentTrack,
LANES_TRACK_GROUP,
'primary-light',
);
}
}
}
}

2
packages/react-reconciler/src/ReactFiberReconciler.js vendored
View File

@ -443,7 +443,7 @@ function updateContainerImpl(
const root = enqueueUpdate(rootFiber, update, lane);
if (root !== null) {
startUpdateTimerByLane(lane);
startUpdateTimerByLane(lane, 'root.render()');
scheduleUpdateOnFiber(root, rootFiber, lane);
entangleTransitions(root, rootFiber, lane);
}

4
packages/react-reconciler/src/ReactFiberWorkLoop.js vendored
View File

@ -264,6 +264,7 @@ import {
import {
blockingClampTime,
blockingUpdateTime,
blockingUpdateTask,
blockingEventTime,
blockingEventType,
blockingEventIsRepeat,
@ -272,6 +273,7 @@ import {
transitionClampTime,
transitionStartTime,
transitionUpdateTime,
transitionUpdateTask,
transitionEventTime,
transitionEventType,
transitionEventIsRepeat,
@ -1914,6 +1916,7 @@ function prepareFreshStack(root: FiberRoot, lanes: Lanes): Fiber {
blockingSpawnedUpdate,
renderStartTime,
lanes,
blockingUpdateTask,
);
clearBlockingTimers();
}
@ -1950,6 +1953,7 @@ function prepareFreshStack(root: FiberRoot, lanes: Lanes): Fiber {
transitionEventType,
transitionEventIsRepeat,
renderStartTime,
transitionUpdateTask,
);
clearTransitionTimers();
}

16
packages/react-reconciler/src/ReactProfilerTimer.js vendored
View File

@ -41,6 +41,13 @@ import * as Scheduler from 'scheduler';
const {unstable_now: now} = Scheduler;
const createTask =
// eslint-disable-next-line react-internal/no-production-logging
__DEV__ && console.createTask
? // eslint-disable-next-line react-internal/no-production-logging
console.createTask
: (name: string) => null;
export let renderStartTime: number = -0;
export let commitStartTime: number = -0;
export let commitEndTime: number = -0;
@ -54,6 +61,7 @@ export let componentEffectErrors: null | Array<CapturedValue<mixed>> = null;
export let blockingClampTime: number = -0;
export let blockingUpdateTime: number = -1.1; // First sync setState scheduled.
export let blockingUpdateTask: null | ConsoleTask = null; // First sync setState's stack trace.
export let blockingEventTime: number = -1.1; // Event timeStamp of the first setState.
export let blockingEventType: null | string = null; // Event type of the first setState.
export let blockingEventIsRepeat: boolean = false;
@ -63,6 +71,7 @@ export let blockingSuspendedTime: number = -1.1;
export let transitionClampTime: number = -0;
export let transitionStartTime: number = -1.1; // First startTransition call before setState.
export let transitionUpdateTime: number = -1.1; // First transition setState scheduled.
export let transitionUpdateTask: null | ConsoleTask = null; // First transition setState's stack trace.
export let transitionEventTime: number = -1.1; // Event timeStamp of the first transition.
export let transitionEventType: null | string = null; // Event type of the first transition.
export let transitionEventIsRepeat: boolean = false;
@ -79,13 +88,14 @@ export function startYieldTimer(reason: SuspendedReason) {
yieldReason = reason;
}
export function startUpdateTimerByLane(lane: Lane): void {
export function startUpdateTimerByLane(lane: Lane, method: string): void {
if (!enableProfilerTimer || !enableComponentPerformanceTrack) {
return;
}
if (isSyncLane(lane) || isBlockingLane(lane)) {
if (blockingUpdateTime < 0) {
blockingUpdateTime = now();
blockingUpdateTask = createTask(method);
if (isAlreadyRendering()) {
blockingSpawnedUpdate = true;
}
@ -108,6 +118,7 @@ export function startUpdateTimerByLane(lane: Lane): void {
} else if (isTransitionLane(lane)) {
if (transitionUpdateTime < 0) {
transitionUpdateTime = now();
transitionUpdateTask = createTask(method);
if (transitionStartTime < 0) {
const newEventTime = resolveEventTimeStamp();
const newEventType = resolveEventType();
@ -155,6 +166,7 @@ export function trackSuspendedTime(lanes: Lanes, renderEndTime: number) {
export function clearBlockingTimers(): void {
blockingUpdateTime = -1.1;
blockingUpdateTask = null;
blockingSuspendedTime = -1.1;
blockingEventIsRepeat = true;
blockingSpawnedUpdate = false;
@ -194,6 +206,7 @@ export function startActionStateUpdate(): void {
}
if (transitionUpdateTime < 0) {
transitionUpdateTime = ACTION_STATE_MARKER;
transitionUpdateTask = null;
}
}
@ -204,6 +217,7 @@ export function clearAsyncTransitionTimer(): void {
export function clearTransitionTimers(): void {
transitionStartTime = -1.1;
transitionUpdateTime = -1.1;
transitionUpdateTask = null;
transitionSuspendedTime = -1.1;
transitionEventIsRepeat = true;
}