diff --git a/packages/react-client/src/ReactFlightPerformanceTrack.js b/packages/react-client/src/ReactFlightPerformanceTrack.js index 8af61d7c5ca58..ed0f67a4f313e 100644 --- a/packages/react-client/src/ReactFlightPerformanceTrack.js +++ b/packages/react-client/src/ReactFlightPerformanceTrack.js @@ -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', + ); + } } } diff --git a/packages/react-reconciler/src/ReactFiberClassComponent.js b/packages/react-reconciler/src/ReactFiberClassComponent.js index a5d7ef12ab6ce..137e22cb12c3e 100644 --- a/packages/react-reconciler/src/ReactFiberClassComponent.js +++ b/packages/react-reconciler/src/ReactFiberClassComponent.js @@ -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); } diff --git a/packages/react-reconciler/src/ReactFiberHooks.js b/packages/react-reconciler/src/ReactFiberHooks.js index 91ed949ca0851..fd3451f406d41 100644 --- a/packages/react-reconciler/src/ReactFiberHooks.js +++ b/packages/react-reconciler/src/ReactFiberHooks.js @@ -1847,6 +1847,8 @@ function updateStoreInstance( // 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( // read from the store. if (checkIfSnapshotChanged(inst)) { // Force a re-render. + startUpdateTimerByLane(SyncLane, 'updateSyncExternalStore()'); forceStoreRerender(fiber); } }; @@ -3503,7 +3506,7 @@ function refreshCache(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( } 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( lane, ); if (didScheduleUpdate) { - startUpdateTimerByLane(lane); + startUpdateTimerByLane(lane, 'setState()'); } markUpdateInDevTools(fiber, lane, action); } @@ -3768,7 +3771,7 @@ function dispatchOptimisticSetState( // 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. diff --git a/packages/react-reconciler/src/ReactFiberPerformanceTrack.js b/packages/react-reconciler/src/ReactFiberPerformanceTrack.js index 8f52fa708b3c9..f94c481c8f02a 100644 --- a/packages/react-reconciler/src/ReactFiberPerformanceTrack.js +++ b/packages/react-reconciler/src/ReactFiberPerformanceTrack.js @@ -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', + ); + } } } } diff --git a/packages/react-reconciler/src/ReactFiberReconciler.js b/packages/react-reconciler/src/ReactFiberReconciler.js index 5de3f0053c861..bcc2500a320c7 100644 --- a/packages/react-reconciler/src/ReactFiberReconciler.js +++ b/packages/react-reconciler/src/ReactFiberReconciler.js @@ -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); } diff --git a/packages/react-reconciler/src/ReactFiberWorkLoop.js b/packages/react-reconciler/src/ReactFiberWorkLoop.js index 3a998aee8d3ed..f5b7bea38e6f8 100644 --- a/packages/react-reconciler/src/ReactFiberWorkLoop.js +++ b/packages/react-reconciler/src/ReactFiberWorkLoop.js @@ -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(); } diff --git a/packages/react-reconciler/src/ReactProfilerTimer.js b/packages/react-reconciler/src/ReactProfilerTimer.js index 16f4ef1ae09b6..b46209a6e6ff4 100644 --- a/packages/react-reconciler/src/ReactProfilerTimer.js +++ b/packages/react-reconciler/src/ReactProfilerTimer.js @@ -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> = 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; }