From cd4e4d759975916a503d14abe46052f9f5826048 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Sebastian=20Markb=C3=A5ge?= Date: Tue, 29 Apr 2025 21:40:10 -0400 Subject: [PATCH 1/2] Use console.timeStamp instead of performance.measure in Component Performance Track (#32736) This is a new extension that Chrome added to the existing `console.timeStamp` similar to the extensions added to `performance.measure`. This one should be significantly faster because it doesn't have the extra object indirection, it doesn't return a `PerformanceMeasure` entry and doesn't register itself with the global system of entries. I also use `performance.measure` in DEV for errors since we can attach the error to the `properties` extension which doesn't exist for `console.timeStamp`. A downside of using this API is that there's no programmatic API for the site itself to collect its own logs from React. Which the previous allowed us to use the standard `performance.getEntries()` for. The recommendation instead will be for the site to patch `console.timeStamp` if it wants to collect measurements from React just like you're recommended to patch `console.error` or `fetch` or whatever to collect other instrumentation metrics. This extension works in Chrome canary but it doesn't yet work fully in Chrome stable. We might want to wait until it has propagated to Chrome to stable. It should be in Chrome 136. --- .../src/ReactFlightPerformanceTrack.js | 123 ++-- .../src/ReactFiberPerformanceTrack.js | 571 ++++++++++-------- scripts/flow/environment.js | 40 ++ 3 files changed, 438 insertions(+), 296 deletions(-) diff --git a/packages/react-client/src/ReactFlightPerformanceTrack.js b/packages/react-client/src/ReactFlightPerformanceTrack.js index 123878526d3eb..8af61d7c5ca58 100644 --- a/packages/react-client/src/ReactFlightPerformanceTrack.js +++ b/packages/react-client/src/ReactFlightPerformanceTrack.js @@ -7,52 +7,35 @@ * @flow */ +/* eslint-disable react-internal/no-production-logging */ + import type {ReactComponentInfo} from 'shared/ReactTypes'; import {enableProfilerTimer} from 'shared/ReactFeatureFlags'; const supportsUserTiming = enableProfilerTimer && - typeof performance !== 'undefined' && - // $FlowFixMe[method-unbinding] - typeof performance.measure === 'function'; + typeof console !== 'undefined' && + typeof console.timeStamp === 'function'; const COMPONENTS_TRACK = 'Server Components ⚛'; -const componentsTrackMarker = { - startTime: 0.001, - detail: { - devtools: { - color: 'primary-light', - track: 'Primary', - trackGroup: COMPONENTS_TRACK, - }, - }, -}; - export function markAllTracksInOrder() { if (supportsUserTiming) { // Ensure we create the Server Component track groups earlier than the Client Scheduler // and Client Components. We can always add the 0 time slot even if it's in the past. // That's still considered for ordering. - performance.mark('Server Components Track', componentsTrackMarker); + console.timeStamp( + 'Server Components Track', + 0.001, + 0.001, + 'Primary', + COMPONENTS_TRACK, + 'primary-light', + ); } } -// Reused to avoid thrashing the GC. -const reusableComponentDevToolDetails = { - color: 'primary', - track: '', - trackGroup: COMPONENTS_TRACK, -}; -const reusableComponentOptions = { - start: -0, - end: -0, - detail: { - devtools: reusableComponentDevToolDetails, - }, -}; - const trackNames = [ 'Primary', 'Parallel', @@ -79,7 +62,7 @@ export function logComponentRender( const name = componentInfo.name; const isPrimaryEnv = env === rootEnv; const selfTime = endTime - startTime; - reusableComponentDevToolDetails.color = + const color = selfTime < 0.5 ? isPrimaryEnv ? 'primary-light' @@ -93,12 +76,16 @@ export function logComponentRender( ? 'primary-dark' : 'secondary-dark' : 'error'; - reusableComponentDevToolDetails.track = trackNames[trackIdx]; - reusableComponentOptions.start = startTime < 0 ? 0 : startTime; - reusableComponentOptions.end = childrenEndTime; const entryName = isPrimaryEnv || env === undefined ? name : name + ' [' + env + ']'; - performance.measure(entryName, reusableComponentOptions); + console.timeStamp( + entryName, + startTime < 0 ? 0 : startTime, + childrenEndTime, + trackNames[trackIdx], + COMPONENTS_TRACK, + color, + ); } } @@ -112,8 +99,17 @@ export function logComponentErrored( error: mixed, ): void { if (supportsUserTiming) { - const properties = []; - if (__DEV__) { + const env = componentInfo.env; + const name = componentInfo.name; + const isPrimaryEnv = env === rootEnv; + const entryName = + isPrimaryEnv || env === undefined ? name : name + ' [' + env + ']'; + if ( + __DEV__ && + typeof performance !== 'undefined' && + // $FlowFixMe[method-unbinding] + typeof performance.measure === 'function' + ) { const message = typeof error === 'object' && error !== null && @@ -122,26 +118,30 @@ export function logComponentErrored( String(error.message) : // eslint-disable-next-line react-internal/safe-string-coercion String(error); - properties.push(['Error', message]); - } - const env = componentInfo.env; - const name = componentInfo.name; - const isPrimaryEnv = env === rootEnv; - const entryName = - isPrimaryEnv || env === undefined ? name : name + ' [' + env + ']'; - performance.measure(entryName, { - start: startTime < 0 ? 0 : startTime, - end: childrenEndTime, - detail: { - devtools: { - color: 'error', - track: trackNames[trackIdx], - trackGroup: COMPONENTS_TRACK, - tooltipText: entryName + ' Errored', - properties, + const properties = [['Error', message]]; + performance.measure(entryName, { + start: startTime < 0 ? 0 : startTime, + end: childrenEndTime, + detail: { + devtools: { + color: 'error', + track: trackNames[trackIdx], + trackGroup: COMPONENTS_TRACK, + tooltipText: entryName + ' Errored', + properties, + }, }, - }, - }); + }); + } else { + console.timeStamp( + entryName, + startTime < 0 ? 0 : startTime, + childrenEndTime, + trackNames[trackIdx], + COMPONENTS_TRACK, + 'error', + ); + } } } @@ -153,11 +153,14 @@ export function logDedupedComponentRender( ): void { if (supportsUserTiming && endTime >= 0 && trackIdx < 10) { const name = componentInfo.name; - reusableComponentDevToolDetails.color = 'tertiary-light'; - reusableComponentDevToolDetails.track = trackNames[trackIdx]; - reusableComponentOptions.start = startTime < 0 ? 0 : startTime; - reusableComponentOptions.end = endTime; const entryName = name + ' [deduped]'; - performance.measure(entryName, reusableComponentOptions); + console.timeStamp( + entryName, + startTime < 0 ? 0 : startTime, + endTime, + trackNames[trackIdx], + COMPONENTS_TRACK, + 'tertiary-light', + ); } } diff --git a/packages/react-reconciler/src/ReactFiberPerformanceTrack.js b/packages/react-reconciler/src/ReactFiberPerformanceTrack.js index 042c3fd927eff..8f52fa708b3c9 100644 --- a/packages/react-reconciler/src/ReactFiberPerformanceTrack.js +++ b/packages/react-reconciler/src/ReactFiberPerformanceTrack.js @@ -7,6 +7,8 @@ * @flow */ +/* eslint-disable react-internal/no-production-logging */ + import type {Fiber} from './ReactInternalTypes'; import type {Lanes} from './ReactFiberLane'; @@ -28,27 +30,14 @@ import {enableProfilerTimer} from 'shared/ReactFeatureFlags'; const supportsUserTiming = enableProfilerTimer && - typeof performance !== 'undefined' && - // $FlowFixMe[method-unbinding] - typeof performance.measure === 'function'; + typeof console !== 'undefined' && + typeof console.timeStamp === 'function'; const COMPONENTS_TRACK = 'Components ⚛'; - -// Reused to avoid thrashing the GC. -const reusableComponentDevToolDetails = { - color: 'primary', - track: COMPONENTS_TRACK, -}; -const reusableComponentOptions = { - start: -0, - end: -0, - detail: { - devtools: reusableComponentDevToolDetails, - }, -}; - const LANES_TRACK_GROUP = 'Scheduler ⚛'; +let currentTrack: string = 'Blocking'; // Lane + const reusableLaneDevToolDetails = { color: 'primary', track: 'Blocking', // Lane @@ -63,63 +52,47 @@ const reusableLaneOptions = { }; export function setCurrentTrackFromLanes(lanes: Lanes): void { - reusableLaneDevToolDetails.track = getGroupNameOfHighestPriorityLane(lanes); + currentTrack = getGroupNameOfHighestPriorityLane(lanes); } -const blockingLaneMarker = { - startTime: 0.003, - detail: { - devtools: { - color: 'primary-light', - track: 'Blocking', - trackGroup: LANES_TRACK_GROUP, - }, - }, -}; - -const transitionLaneMarker = { - startTime: 0.003, - detail: { - devtools: { - color: 'primary-light', - track: 'Transition', - trackGroup: LANES_TRACK_GROUP, - }, - }, -}; - -const suspenseLaneMarker = { - startTime: 0.003, - detail: { - devtools: { - color: 'primary-light', - track: 'Suspense', - trackGroup: LANES_TRACK_GROUP, - }, - }, -}; - -const idleLaneMarker = { - startTime: 0.003, - detail: { - devtools: { - color: 'primary-light', - track: 'Idle', - trackGroup: LANES_TRACK_GROUP, - }, - }, -}; - export function markAllLanesInOrder() { if (supportsUserTiming) { // Ensure we create all tracks in priority order. Currently performance.mark() are in // first insertion order but performance.measure() are in the reverse order. We can // always add the 0 time slot even if it's in the past. That's still considered for // ordering. - performance.mark('Blocking Track', blockingLaneMarker); - performance.mark('Transition Track', transitionLaneMarker); - performance.mark('Suspense Track', suspenseLaneMarker); - performance.mark('Idle Track', idleLaneMarker); + console.timeStamp( + 'Blocking Track', + 0.003, + 0.003, + 'Blocking', + LANES_TRACK_GROUP, + 'primary-light', + ); + console.timeStamp( + 'Transition Track', + 0.003, + 0.003, + 'Transition', + LANES_TRACK_GROUP, + 'primary-light', + ); + console.timeStamp( + 'Suspense Track', + 0.003, + 0.003, + 'Suspense', + LANES_TRACK_GROUP, + 'primary-light', + ); + console.timeStamp( + 'Idle Track', + 0.003, + 0.003, + 'Idle', + LANES_TRACK_GROUP, + 'primary-light', + ); } } @@ -130,10 +103,14 @@ function logComponentTrigger( trigger: string, ) { if (supportsUserTiming) { - reusableComponentDevToolDetails.color = 'warning'; - reusableComponentOptions.start = startTime; - reusableComponentOptions.end = endTime; - performance.measure(trigger, reusableComponentOptions); + console.timeStamp( + trigger, + startTime, + endTime, + COMPONENTS_TRACK, + undefined, + 'warning', + ); } } @@ -187,7 +164,7 @@ export function logComponentRender( selfTime -= (child.actualDuration: any); } } - reusableComponentDevToolDetails.color = + const color = selfTime < 0.5 ? wasHydrated ? 'tertiary-light' @@ -201,9 +178,14 @@ export function logComponentRender( ? 'tertiary-dark' : 'primary-dark' : 'error'; - reusableComponentOptions.start = startTime; - reusableComponentOptions.end = endTime; - performance.measure(name, reusableComponentOptions); + console.timeStamp( + name, + startTime, + endTime, + COMPONENTS_TRACK, + undefined, + color, + ); } } @@ -219,8 +201,13 @@ export function logComponentErrored( // Skip return; } - const properties = []; - if (__DEV__) { + if ( + __DEV__ && + typeof performance !== 'undefined' && + // $FlowFixMe[method-unbinding] + typeof performance.measure === 'function' + ) { + const properties = []; for (let i = 0; i < errors.length; i++) { const capturedValue = errors[i]; const error = capturedValue.value; @@ -234,22 +221,31 @@ export function logComponentErrored( String(error); properties.push(['Error', message]); } - } - performance.measure(name, { - start: startTime, - end: endTime, - detail: { - devtools: { - color: 'error', - track: COMPONENTS_TRACK, - tooltipText: - fiber.tag === SuspenseComponent - ? 'Hydration failed' - : 'Error boundary caught an error', - properties, + performance.measure(name, { + start: startTime, + end: endTime, + detail: { + devtools: { + color: 'error', + track: COMPONENTS_TRACK, + tooltipText: + fiber.tag === SuspenseComponent + ? 'Hydration failed' + : 'Error boundary caught an error', + properties, + }, }, - }, - }); + }); + } else { + console.timeStamp( + name, + startTime, + endTime, + COMPONENTS_TRACK, + undefined, + 'error', + ); + } } } @@ -265,8 +261,13 @@ function logComponentEffectErrored( // Skip return; } - const properties = []; - if (__DEV__) { + if ( + __DEV__ && + typeof performance !== 'undefined' && + // $FlowFixMe[method-unbinding] + typeof performance.measure === 'function' + ) { + const properties = []; for (let i = 0; i < errors.length; i++) { const capturedValue = errors[i]; const error = capturedValue.value; @@ -280,19 +281,28 @@ function logComponentEffectErrored( String(error); properties.push(['Error', message]); } - } - performance.measure(name, { - start: startTime, - end: endTime, - detail: { - devtools: { - color: 'error', - track: COMPONENTS_TRACK, - tooltipText: 'A lifecycle or effect errored', - properties, + performance.measure(name, { + start: startTime, + end: endTime, + detail: { + devtools: { + color: 'error', + track: COMPONENTS_TRACK, + tooltipText: 'A lifecycle or effect errored', + properties, + }, }, - }, - }); + }); + } else { + console.timeStamp( + name, + startTime, + endTime, + COMPONENTS_TRACK, + undefined, + 'error', + ); + } } } @@ -313,7 +323,7 @@ export function logComponentEffect( return; } if (supportsUserTiming) { - reusableComponentDevToolDetails.color = + const color = selfTime < 1 ? 'secondary-light' : selfTime < 100 @@ -321,9 +331,14 @@ export function logComponentEffect( : selfTime < 500 ? 'secondary-dark' : 'error'; - reusableComponentOptions.start = startTime; - reusableComponentOptions.end = endTime; - performance.measure(name, reusableComponentOptions); + console.timeStamp( + name, + startTime, + endTime, + COMPONENTS_TRACK, + undefined, + color, + ); } } @@ -335,7 +350,7 @@ export function logYieldTime(startTime: number, endTime: number): void { return; } // Being blocked on CPU is potentially bad so we color it by how long it took. - reusableComponentDevToolDetails.color = + const color = yieldDuration < 5 ? 'primary-light' : yieldDuration < 10 @@ -343,13 +358,18 @@ export function logYieldTime(startTime: number, endTime: number): void { : yieldDuration < 100 ? 'primary-dark' : 'error'; - reusableComponentOptions.start = startTime; - reusableComponentOptions.end = endTime; // This get logged in the components track if we don't commit which leaves them // hanging by themselves without context. It's a useful indicator for why something // might be starving this render though. // TODO: Considering adding these to a queue and only logging them if we commit. - performance.measure('Blocked', reusableComponentOptions); + console.timeStamp( + 'Blocked', + startTime, + endTime, + COMPONENTS_TRACK, + undefined, + color, + ); } } @@ -359,10 +379,14 @@ export function logSuspendedYieldTime( suspendedFiber: Fiber, ): void { if (supportsUserTiming) { - reusableComponentDevToolDetails.color = 'primary-light'; - reusableComponentOptions.start = startTime; - reusableComponentOptions.end = endTime; - performance.measure('Suspended', reusableComponentOptions); + console.timeStamp( + 'Suspended', + startTime, + endTime, + COMPONENTS_TRACK, + undefined, + 'primary-light', + ); } } @@ -372,10 +396,14 @@ export function logActionYieldTime( suspendedFiber: Fiber, ): void { if (supportsUserTiming) { - reusableComponentDevToolDetails.color = 'primary-light'; - reusableComponentOptions.start = startTime; - reusableComponentOptions.end = endTime; - performance.measure('Action', reusableComponentOptions); + console.timeStamp( + 'Action', + startTime, + endTime, + COMPONENTS_TRACK, + undefined, + 'primary-light', + ); } } @@ -389,38 +417,40 @@ export function logBlockingStart( lanes: Lanes, ): void { if (supportsUserTiming) { - reusableLaneDevToolDetails.track = 'Blocking'; + currentTrack = 'Blocking'; // 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. if (eventTime > 0 && eventType !== null) { // Log the time from the event timeStamp until we called setState. - reusableLaneDevToolDetails.color = eventIsRepeat - ? 'secondary-light' - : 'warning'; - reusableLaneOptions.start = eventTime; - reusableLaneOptions.end = updateTime > 0 ? updateTime : renderStartTime; - performance.measure( + const color = eventIsRepeat ? 'secondary-light' : 'warning'; + console.timeStamp( eventIsRepeat ? '' : 'Event: ' + eventType, - reusableLaneOptions, + 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. - reusableLaneDevToolDetails.color = isSpawnedUpdate + const color = isSpawnedUpdate ? 'error' : includesOnlyHydrationOrOffscreenLanes(lanes) ? 'tertiary-light' : 'primary-light'; - reusableLaneOptions.start = updateTime; - reusableLaneOptions.end = renderStartTime; - performance.measure( + console.timeStamp( isSpawnedUpdate ? 'Cascading Update' : renderStartTime - updateTime > 5 ? 'Update Blocked' : 'Update', - reusableLaneOptions, + updateTime, + renderStartTime, + currentTrack, + LANES_TRACK_GROUP, + color, ); } } @@ -435,39 +465,45 @@ export function logTransitionStart( renderStartTime: number, ): void { if (supportsUserTiming) { - reusableLaneDevToolDetails.track = 'Transition'; + currentTrack = 'Transition'; if (eventTime > 0 && eventType !== null) { // Log the time from the event timeStamp until we started a transition. - reusableLaneDevToolDetails.color = eventIsRepeat - ? 'secondary-light' - : 'warning'; - reusableLaneOptions.start = eventTime; - reusableLaneOptions.end = + const color = eventIsRepeat ? 'secondary-light' : 'warning'; + const endTime = startTime > 0 ? startTime : updateTime > 0 ? updateTime : renderStartTime; - performance.measure( + console.timeStamp( eventIsRepeat ? '' : 'Event: ' + eventType, - reusableLaneOptions, + 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. - reusableLaneDevToolDetails.color = 'primary-dark'; - reusableLaneOptions.start = startTime; - reusableLaneOptions.end = updateTime > 0 ? updateTime : renderStartTime; - performance.measure('Action', reusableLaneOptions); + 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. - reusableLaneDevToolDetails.color = 'primary-light'; - reusableLaneOptions.start = updateTime; - reusableLaneOptions.end = renderStartTime; - performance.measure( + console.timeStamp( renderStartTime - updateTime > 5 ? 'Update Blocked' : 'Update', - reusableLaneOptions, + updateTime, + renderStartTime, + currentTrack, + LANES_TRACK_GROUP, + 'primary-light', ); } } @@ -479,20 +515,20 @@ export function logRenderPhase( lanes: Lanes, ): void { if (supportsUserTiming) { - reusableLaneDevToolDetails.color = includesOnlyHydrationOrOffscreenLanes( - lanes, - ) + const color = includesOnlyHydrationOrOffscreenLanes(lanes) ? 'tertiary-dark' : 'primary-dark'; - reusableLaneOptions.start = startTime; - reusableLaneOptions.end = endTime; - performance.measure( + console.timeStamp( includesOnlyOffscreenLanes(lanes) ? 'Prepared' : includesOnlyHydrationLanes(lanes) ? 'Hydrated' : 'Render', - reusableLaneOptions, + startTime, + endTime, + currentTrack, + LANES_TRACK_GROUP, + color, ); } } @@ -503,20 +539,20 @@ export function logInterruptedRenderPhase( lanes: Lanes, ): void { if (supportsUserTiming) { - reusableLaneDevToolDetails.color = includesOnlyHydrationOrOffscreenLanes( - lanes, - ) + const color = includesOnlyHydrationOrOffscreenLanes(lanes) ? 'tertiary-dark' : 'primary-dark'; - reusableLaneOptions.start = startTime; - reusableLaneOptions.end = endTime; - performance.measure( + console.timeStamp( includesOnlyOffscreenLanes(lanes) ? 'Prewarm' : includesOnlyHydrationLanes(lanes) ? 'Interrupted Hydration' : 'Interrupted Render', - reusableLaneOptions, + startTime, + endTime, + currentTrack, + LANES_TRACK_GROUP, + color, ); } } @@ -527,14 +563,17 @@ export function logSuspendedRenderPhase( lanes: Lanes, ): void { if (supportsUserTiming) { - reusableLaneDevToolDetails.color = includesOnlyHydrationOrOffscreenLanes( - lanes, - ) + const color = includesOnlyHydrationOrOffscreenLanes(lanes) ? 'tertiary-dark' : 'primary-dark'; - reusableLaneOptions.start = startTime; - reusableLaneOptions.end = endTime; - performance.measure('Prewarm', reusableLaneOptions); + console.timeStamp( + 'Prewarm', + startTime, + endTime, + currentTrack, + LANES_TRACK_GROUP, + color, + ); } } @@ -545,14 +584,17 @@ export function logSuspendedWithDelayPhase( ): void { // This means the render was suspended and cannot commit until it gets unblocked. if (supportsUserTiming) { - reusableLaneDevToolDetails.color = includesOnlyHydrationOrOffscreenLanes( - lanes, - ) + const color = includesOnlyHydrationOrOffscreenLanes(lanes) ? 'tertiary-dark' : 'primary-dark'; - reusableLaneOptions.start = startTime; - reusableLaneOptions.end = endTime; - performance.measure('Suspended', reusableLaneOptions); + console.timeStamp( + 'Suspended', + startTime, + endTime, + currentTrack, + LANES_TRACK_GROUP, + color, + ); } } @@ -564,8 +606,13 @@ export function logRecoveredRenderPhase( hydrationFailed: boolean, ): void { if (supportsUserTiming) { - const properties = []; - if (__DEV__) { + if ( + __DEV__ && + typeof performance !== 'undefined' && + // $FlowFixMe[method-unbinding] + typeof performance.measure === 'function' + ) { + const properties = []; for (let i = 0; i < recoverableErrors.length; i++) { const capturedValue = recoverableErrors[i]; const error = capturedValue.value; @@ -579,22 +626,31 @@ export function logRecoveredRenderPhase( String(error); properties.push(['Recoverable Error', message]); } - } - performance.measure('Recovered', { - start: startTime, - end: endTime, - detail: { - devtools: { - color: 'primary-dark', - track: reusableLaneDevToolDetails.track, - trackGroup: LANES_TRACK_GROUP, - tooltipText: hydrationFailed - ? 'Hydration Failed' - : 'Recovered after Error', - properties, + performance.measure('Recovered', { + start: startTime, + end: endTime, + detail: { + devtools: { + color: 'primary-dark', + track: currentTrack, + trackGroup: LANES_TRACK_GROUP, + tooltipText: hydrationFailed + ? 'Hydration Failed' + : 'Recovered after Error', + properties, + }, }, - }, - }); + }); + } else { + console.timeStamp( + 'Recovered', + startTime, + endTime, + currentTrack, + LANES_TRACK_GROUP, + 'error', + ); + } } } @@ -604,10 +660,14 @@ export function logErroredRenderPhase( lanes: Lanes, ): void { if (supportsUserTiming) { - reusableLaneDevToolDetails.color = 'error'; - reusableLaneOptions.start = startTime; - reusableLaneOptions.end = endTime; - performance.measure('Errored', reusableLaneOptions); + console.timeStamp( + 'Errored', + startTime, + endTime, + currentTrack, + LANES_TRACK_GROUP, + 'error', + ); } } @@ -616,10 +676,14 @@ export function logInconsistentRender( endTime: number, ): void { if (supportsUserTiming) { - reusableLaneDevToolDetails.color = 'error'; - reusableLaneOptions.start = startTime; - reusableLaneOptions.end = endTime; - performance.measure('Teared Render', reusableLaneOptions); + console.timeStamp( + 'Teared Render', + startTime, + endTime, + currentTrack, + LANES_TRACK_GROUP, + 'error', + ); } } @@ -629,10 +693,14 @@ export function logSuspenseThrottlePhase( ): void { // This was inside a throttled Suspense boundary commit. if (supportsUserTiming) { - reusableLaneDevToolDetails.color = 'secondary-light'; - reusableLaneOptions.start = startTime; - reusableLaneOptions.end = endTime; - performance.measure('Throttled', reusableLaneOptions); + console.timeStamp( + 'Throttled', + startTime, + endTime, + currentTrack, + LANES_TRACK_GROUP, + 'secondary-light', + ); } } @@ -642,12 +710,16 @@ export function logSuspendedCommitPhase( ): void { // This means the commit was suspended on CSS or images. if (supportsUserTiming) { - reusableLaneDevToolDetails.color = 'secondary-light'; - reusableLaneOptions.start = startTime; - reusableLaneOptions.end = endTime; // TODO: Include the exact reason and URLs of what resources suspended. // TODO: This might also be Suspended while waiting on a View Transition. - performance.measure('Suspended on CSS or Images', reusableLaneOptions); + console.timeStamp( + 'Suspended on CSS or Images', + startTime, + endTime, + currentTrack, + LANES_TRACK_GROUP, + 'secondary-light', + ); } } @@ -658,8 +730,13 @@ export function logCommitErrored( passive: boolean, ): void { if (supportsUserTiming) { - const properties = []; - if (__DEV__) { + if ( + __DEV__ && + typeof performance !== 'undefined' && + // $FlowFixMe[method-unbinding] + typeof performance.measure === 'function' + ) { + const properties = []; for (let i = 0; i < errors.length; i++) { const capturedValue = errors[i]; const error = capturedValue.value; @@ -673,20 +750,31 @@ export function logCommitErrored( String(error); properties.push(['Error', message]); } - } - performance.measure('Errored', { - start: startTime, - end: endTime, - detail: { - devtools: { - color: 'error', - track: reusableLaneDevToolDetails.track, - trackGroup: LANES_TRACK_GROUP, - tooltipText: passive ? 'Remaining Effects Errored' : 'Commit Errored', - properties, + performance.measure('Errored', { + start: startTime, + end: endTime, + detail: { + devtools: { + color: 'error', + track: currentTrack, + trackGroup: LANES_TRACK_GROUP, + tooltipText: passive + ? 'Remaining Effects Errored' + : 'Commit Errored', + properties, + }, }, - }, - }); + }); + } else { + console.timeStamp( + 'Errored', + startTime, + endTime, + currentTrack, + LANES_TRACK_GROUP, + 'error', + ); + } } } @@ -700,10 +788,16 @@ export function logCommitPhase( return; } if (supportsUserTiming) { - reusableLaneDevToolDetails.color = 'secondary-dark'; reusableLaneOptions.start = startTime; reusableLaneOptions.end = endTime; - performance.measure('Commit', reusableLaneOptions); + console.timeStamp( + 'Commit', + startTime, + endTime, + currentTrack, + LANES_TRACK_GROUP, + 'secondary-dark', + ); } } @@ -713,12 +807,13 @@ export function logPaintYieldPhase( delayedUntilPaint: boolean, ): void { if (supportsUserTiming) { - reusableLaneDevToolDetails.color = 'secondary-light'; - reusableLaneOptions.start = startTime; - reusableLaneOptions.end = endTime; - performance.measure( + console.timeStamp( delayedUntilPaint ? 'Waiting for Paint' : '', - reusableLaneOptions, + startTime, + endTime, + currentTrack, + LANES_TRACK_GROUP, + 'secondary-light', ); } } @@ -733,9 +828,13 @@ export function logPassiveCommitPhase( return; } if (supportsUserTiming) { - reusableLaneDevToolDetails.color = 'secondary-dark'; - reusableLaneOptions.start = startTime; - reusableLaneOptions.end = endTime; - performance.measure('Remaining Effects', reusableLaneOptions); + console.timeStamp( + 'Remaining Effects', + startTime, + endTime, + currentTrack, + LANES_TRACK_GROUP, + 'secondary-dark', + ); } } diff --git a/scripts/flow/environment.js b/scripts/flow/environment.js index 96784a8353383..c3fe40eeef302 100644 --- a/scripts/flow/environment.js +++ b/scripts/flow/environment.js @@ -33,6 +33,46 @@ declare interface ConsoleTask { run(f: () => T): T; } +declare var console: { + assert(condition: mixed, ...data: Array): void, + clear(): void, + count(label?: string): void, + countReset(label?: string): void, + debug(...data: Array): void, + dir(...data: Array): void, + dirxml(...data: Array): void, + error(...data: Array): void, + _exception(...data: Array): void, + group(...data: Array): void, + groupCollapsed(...data: Array): void, + groupEnd(): void, + info(...data: Array): void, + log(...data: Array): void, + profile(name?: string): void, + profileEnd(name?: string): void, + table( + tabularData: + | {[key: string]: any, ...} + | Array<{[key: string]: any, ...}> + | Array>, + ): void, + time(label?: string): void, + timeEnd(label: string): void, + timeStamp( + label?: string, + start?: string | number, + end?: string | number, + trackName?: string, + trackGroup?: string, + color?: string, + ): void, + timeLog(label?: string, ...data?: Array): void, + trace(...data: Array): void, + warn(...data: Array): void, + createTask(label: string): ConsoleTask, + ... +}; + type ScrollTimelineOptions = { source: Element, axis?: 'block' | 'inline' | 'x' | 'y', From 62960c67c84da7e85d7515ef8447cea0ba0824a6 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Sebastian=20Markb=C3=A5ge?= Date: Tue, 29 Apr 2025 22:17:17 -0400 Subject: [PATCH 2/2] Run Component Track Logs in the console.createTask() of the Fiber (#32809) 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. --- .../src/ReactFlightPerformanceTrack.js | 64 ++- .../src/ReactFiberClassComponent.js | 6 +- .../react-reconciler/src/ReactFiberHooks.js | 11 +- .../src/ReactFiberPerformanceTrack.js | 368 +++++++++++++----- .../src/ReactFiberReconciler.js | 2 +- .../src/ReactFiberWorkLoop.js | 4 + .../src/ReactProfilerTimer.js | 16 +- 7 files changed, 358 insertions(+), 113 deletions(-) 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; }