diff --git a/packages/react-client/src/ReactFlightPerformanceTrack.js b/packages/react-client/src/ReactFlightPerformanceTrack.js index 123878526d3eb..ed0f67a4f313e 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,32 @@ 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); + 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, + ); + } } } @@ -112,8 +115,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 +134,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 +169,30 @@ 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); + 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 042c3fd927eff..f94c481c8f02a 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,29 @@ function logComponentTrigger( trigger: string, ) { if (supportsUserTiming) { - reusableComponentDevToolDetails.color = 'warning'; - reusableComponentOptions.start = startTime; - reusableComponentOptions.end = endTime; - performance.measure(trigger, reusableComponentOptions); + 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', + ); + } } } @@ -187,7 +179,7 @@ export function logComponentRender( selfTime -= (child.actualDuration: any); } } - reusableComponentDevToolDetails.color = + const color = selfTime < 0.5 ? wasHydrated ? 'tertiary-light' @@ -201,9 +193,30 @@ export function logComponentRender( ? 'tertiary-dark' : 'primary-dark' : 'error'; - reusableComponentOptions.start = startTime; - reusableComponentOptions.end = endTime; - performance.measure(name, reusableComponentOptions); + 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, + ); + } } } @@ -219,10 +232,24 @@ export function logComponentErrored( // Skip return; } - const properties = []; - if (__DEV__) { + if ( + __DEV__ && + typeof performance !== 'undefined' && + // $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' && @@ -234,22 +261,44 @@ 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, + 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: { + devtools: { + color: 'error', + track: COMPONENTS_TRACK, + tooltipText: + fiber.tag === SuspenseComponent + ? 'Hydration failed' + : 'Error boundary caught an error', + properties, + }, }, - }, - }); + }; + if (__DEV__ && debugTask) { + debugTask.run( + // $FlowFixMe[method-unbinding] + performance.measure.bind(performance, name, options), + ); + } else { + performance.measure(name, options); + } + } else { + console.timeStamp( + name, + startTime, + endTime, + COMPONENTS_TRACK, + undefined, + 'error', + ); + } } } @@ -265,8 +314,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 +334,37 @@ 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, + const options = { + start: startTime, + end: endTime, + detail: { + devtools: { + color: 'error', + track: COMPONENTS_TRACK, + tooltipText: 'A lifecycle or effect errored', + 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, + startTime, + endTime, + COMPONENTS_TRACK, + undefined, + 'error', + ); + } } } @@ -313,7 +385,7 @@ export function logComponentEffect( return; } if (supportsUserTiming) { - reusableComponentDevToolDetails.color = + const color = selfTime < 1 ? 'secondary-light' : selfTime < 100 @@ -321,9 +393,30 @@ export function logComponentEffect( : selfTime < 500 ? 'secondary-dark' : 'error'; - reusableComponentOptions.start = startTime; - reusableComponentOptions.end = endTime; - performance.measure(name, reusableComponentOptions); + 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, + ); + } } } @@ -335,7 +428,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 +436,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 +457,30 @@ export function logSuspendedYieldTime( suspendedFiber: Fiber, ): void { if (supportsUserTiming) { - reusableComponentDevToolDetails.color = 'primary-light'; - reusableComponentOptions.start = startTime; - reusableComponentOptions.end = endTime; - performance.measure('Suspended', reusableComponentOptions); + 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', + ); + } } } @@ -372,10 +490,30 @@ export function logActionYieldTime( suspendedFiber: Fiber, ): void { if (supportsUserTiming) { - reusableComponentDevToolDetails.color = 'primary-light'; - reusableComponentOptions.start = startTime; - reusableComponentOptions.end = endTime; - performance.measure('Action', reusableComponentOptions); + 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', + ); + } } } @@ -387,41 +525,78 @@ export function logBlockingStart( isSpawnedUpdate: boolean, renderStartTime: number, lanes: Lanes, + debugTask: null | ConsoleTask, // DEV-only ): 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( - eventIsRepeat ? '' : 'Event: ' + eventType, - reusableLaneOptions, - ); + const color = eventIsRepeat ? 'secondary-light' : 'warning'; + 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. - reusableLaneDevToolDetails.color = isSpawnedUpdate + const color = isSpawnedUpdate ? 'error' : includesOnlyHydrationOrOffscreenLanes(lanes) ? 'tertiary-light' : 'primary-light'; - reusableLaneOptions.start = updateTime; - reusableLaneOptions.end = renderStartTime; - performance.measure( - isSpawnedUpdate - ? 'Cascading Update' - : renderStartTime - updateTime > 5 - ? 'Update Blocked' - : 'Update', - reusableLaneOptions, - ); + 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, + ); + } } } } @@ -433,42 +608,95 @@ export function logTransitionStart( eventType: null | string, eventIsRepeat: boolean, renderStartTime: number, + debugTask: null | ConsoleTask, // DEV-only ): 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( - eventIsRepeat ? '' : 'Event: ' + eventType, - reusableLaneOptions, - ); + 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. - reusableLaneDevToolDetails.color = 'primary-dark'; - reusableLaneOptions.start = startTime; - reusableLaneOptions.end = updateTime > 0 ? updateTime : renderStartTime; - performance.measure('Action', reusableLaneOptions); + // 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. - reusableLaneDevToolDetails.color = 'primary-light'; - reusableLaneOptions.start = updateTime; - reusableLaneOptions.end = renderStartTime; - performance.measure( - renderStartTime - updateTime > 5 ? 'Update Blocked' : 'Update', - reusableLaneOptions, - ); + 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', + ); + } } } } @@ -479,20 +707,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 +731,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 +755,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 +776,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 +798,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 +818,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 +852,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 +868,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 +885,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 +902,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 +922,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 +942,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 +980,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 +999,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 +1020,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/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; } 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',