From d4688dfaafe51a4cb6e3c51fc2330662cb4e2296 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Sebastian=20Markb=C3=A5ge?= Date: Fri, 20 Sep 2024 14:27:12 -0400 Subject: [PATCH] [Fiber] Track Event Time, startTransition Time and setState Time (#31008) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit This tracks the current window.event.timeStamp the first time we setState or call startTransition. For either the blocking track or transition track. We can use this to show how long we were blocked by other events or overhead from when the user interacted until we got called into React. Then we track the time we start awaiting a Promise returned from startTransition. We can use this track how long we waited on an Action to complete before setState was called. Then finally we track when setState was called so we can track how long we were blocked by other word before we could actually start rendering. For a Transition this might be blocked by Blocking React render work. We only log these once a subsequent render actually happened. If no render was actually scheduled, then we don't log these. E.g. if an isomorphic Action doesn't call startTransition there's no render so we don't log it. We only log the first event/update/transition even if multiple are batched into it later. If multiple Actions are entangled they're all treated as one until an update happens. If no update happens and all entangled actions finish, we clear the transition so that the next time a new sequence starts we can log it. We also clamp these (start the track later) if they were scheduled within a render/commit. Since we share a single track we don't want to create overlapping tracks. The purpose of this is not to show every event/action that happens but to show a prelude to how long we were blocked before a render started. So you can follow the first event to commit. Screenshot 2024-09-20 at 1 59 58 AM I still need to add the rendering/suspended phases to the timeline which why this screenshot has a gap. Screenshot 2024-09-20 at 12 50 27 AM In this case it's a Form Action which started a render into the form which then suspended on the action. The action then caused a refresh, which interrupts with its own update that's blocked before rendering. Suspended roots like this is interesting because we could in theory start working on a different root in the meantime which makes this timeline less linear. --- packages/react-art/src/ReactFiberConfigART.js | 8 ++ .../src/client/ReactFiberConfigDOM.js | 10 ++ .../src/ReactFiberConfigFabric.js | 8 ++ .../src/ReactFiberConfigNative.js | 8 ++ .../src/createReactNoop.js | 8 ++ .../src/ReactFiberAsyncAction.js | 52 +++++--- .../src/ReactFiberClassComponent.js | 4 + .../react-reconciler/src/ReactFiberHooks.js | 69 ++++++++-- .../react-reconciler/src/ReactFiberLane.js | 17 +++ .../src/ReactFiberPerformanceTrack.js | 65 ++++++++++ .../src/ReactFiberReconciler.js | 2 + .../src/ReactFiberTransition.js | 8 ++ .../src/ReactFiberWorkLoop.js | 70 +++++++++++ .../src/ReactProfilerTimer.js | 119 ++++++++++++++++++ .../ReactFiberHostContext-test.internal.js | 6 + .../src/forks/ReactFiberConfig.custom.js | 2 + .../src/ReactFiberConfigTestHost.js | 7 ++ .../__tests__/ReactProfiler-test.internal.js | 6 + 18 files changed, 443 insertions(+), 26 deletions(-) diff --git a/packages/react-art/src/ReactFiberConfigART.js b/packages/react-art/src/ReactFiberConfigART.js index 816353e0ced2f..33bbe055724d9 100644 --- a/packages/react-art/src/ReactFiberConfigART.js +++ b/packages/react-art/src/ReactFiberConfigART.js @@ -363,6 +363,14 @@ export function resolveUpdatePriority(): EventPriority { return currentUpdatePriority || DefaultEventPriority; } +export function resolveEventType(): null | string { + return null; +} + +export function resolveEventTimeStamp(): number { + return -1.1; +} + export function shouldAttemptEagerTransition() { return false; } diff --git a/packages/react-dom-bindings/src/client/ReactFiberConfigDOM.js b/packages/react-dom-bindings/src/client/ReactFiberConfigDOM.js index 0e39f988f813c..d46f61035b8d4 100644 --- a/packages/react-dom-bindings/src/client/ReactFiberConfigDOM.js +++ b/packages/react-dom-bindings/src/client/ReactFiberConfigDOM.js @@ -606,6 +606,16 @@ export function shouldAttemptEagerTransition(): boolean { return false; } +export function resolveEventType(): null | string { + const event = window.event; + return event ? event.type : null; +} + +export function resolveEventTimeStamp(): number { + const event = window.event; + return event ? event.timeStamp : -1.1; +} + export const isPrimaryRenderer = true; export const warnsIfNotActing = true; // This initialization code may run even on server environments diff --git a/packages/react-native-renderer/src/ReactFiberConfigFabric.js b/packages/react-native-renderer/src/ReactFiberConfigFabric.js index 80215d11ec14c..10f7c6ecd84a3 100644 --- a/packages/react-native-renderer/src/ReactFiberConfigFabric.js +++ b/packages/react-native-renderer/src/ReactFiberConfigFabric.js @@ -372,6 +372,14 @@ export function resolveUpdatePriority(): EventPriority { return DefaultEventPriority; } +export function resolveEventType(): null | string { + return null; +} + +export function resolveEventTimeStamp(): number { + return -1.1; +} + export function shouldAttemptEagerTransition(): boolean { return false; } diff --git a/packages/react-native-renderer/src/ReactFiberConfigNative.js b/packages/react-native-renderer/src/ReactFiberConfigNative.js index 0a95e0f818cdb..1dc8c627b1ccb 100644 --- a/packages/react-native-renderer/src/ReactFiberConfigNative.js +++ b/packages/react-native-renderer/src/ReactFiberConfigNative.js @@ -288,6 +288,14 @@ export function resolveUpdatePriority(): EventPriority { return DefaultEventPriority; } +export function resolveEventType(): null | string { + return null; +} + +export function resolveEventTimeStamp(): number { + return -1.1; +} + export function shouldAttemptEagerTransition(): boolean { return false; } diff --git a/packages/react-noop-renderer/src/createReactNoop.js b/packages/react-noop-renderer/src/createReactNoop.js index 859bab499b6f3..55e0fd24c9b9b 100644 --- a/packages/react-noop-renderer/src/createReactNoop.js +++ b/packages/react-noop-renderer/src/createReactNoop.js @@ -533,6 +533,14 @@ function createReactNoop(reconciler: Function, useMutation: boolean) { return currentEventPriority; }, + resolveEventType(): null | string { + return null; + }, + + resolveEventTimeStamp(): number { + return -1.1; + }, + shouldAttemptEagerTransition(): boolean { return false; }, diff --git a/packages/react-reconciler/src/ReactFiberAsyncAction.js b/packages/react-reconciler/src/ReactFiberAsyncAction.js index ec53c7d80346c..4d210d02ac827 100644 --- a/packages/react-reconciler/src/ReactFiberAsyncAction.js +++ b/packages/react-reconciler/src/ReactFiberAsyncAction.js @@ -17,6 +17,14 @@ import type {BatchConfigTransition} from './ReactFiberTracingMarkerComponent'; import {requestTransitionLane} from './ReactFiberRootScheduler'; import {NoLane} from './ReactFiberLane'; +import { + hasScheduledTransitionWork, + clearAsyncTransitionTimer, +} from './ReactProfilerTimer'; +import { + enableComponentPerformanceTrack, + enableProfilerTimer, +} from 'shared/ReactFeatureFlags'; // If there are multiple, concurrent async actions, they are entangled. All // transition updates that occur while the async action is still in progress @@ -64,24 +72,34 @@ export function entangleAsyncAction( } function pingEngtangledActionScope() { - if ( - currentEntangledListeners !== null && - --currentEntangledPendingCount === 0 - ) { - // All the actions have finished. Close the entangled async action scope - // and notify all the listeners. - if (currentEntangledActionThenable !== null) { - const fulfilledThenable: FulfilledThenable = - (currentEntangledActionThenable: any); - fulfilledThenable.status = 'fulfilled'; + if (--currentEntangledPendingCount === 0) { + if (enableProfilerTimer && enableComponentPerformanceTrack) { + if (!hasScheduledTransitionWork()) { + // If we have received no updates since we started the entangled Actions + // that means it didn't lead to a Transition being rendered. We need to + // clear the timer so that if we start another entangled sequence we use + // the next start timer instead of appearing like we were blocked the + // whole time. We currently don't log a track for Actions that don't + // render a Transition. + clearAsyncTransitionTimer(); + } } - const listeners = currentEntangledListeners; - currentEntangledListeners = null; - currentEntangledLane = NoLane; - currentEntangledActionThenable = null; - for (let i = 0; i < listeners.length; i++) { - const listener = listeners[i]; - listener(); + if (currentEntangledListeners !== null) { + // All the actions have finished. Close the entangled async action scope + // and notify all the listeners. + if (currentEntangledActionThenable !== null) { + const fulfilledThenable: FulfilledThenable = + (currentEntangledActionThenable: any); + fulfilledThenable.status = 'fulfilled'; + } + const listeners = currentEntangledListeners; + currentEntangledListeners = null; + currentEntangledLane = NoLane; + currentEntangledActionThenable = null; + for (let i = 0; i < listeners.length; i++) { + const listener = listeners[i]; + listener(); + } } } } diff --git a/packages/react-reconciler/src/ReactFiberClassComponent.js b/packages/react-reconciler/src/ReactFiberClassComponent.js index f1419d1aad047..79c516eacf117 100644 --- a/packages/react-reconciler/src/ReactFiberClassComponent.js +++ b/packages/react-reconciler/src/ReactFiberClassComponent.js @@ -72,6 +72,7 @@ import { markStateUpdateScheduled, setIsStrictModeForDevtools, } from './ReactFiberDevToolsHook'; +import {startUpdateTimerByLane} from './ReactProfilerTimer'; const fakeInternalInstance = {}; @@ -194,6 +195,7 @@ const classComponentUpdater = { const root = enqueueUpdate(fiber, update, lane); if (root !== null) { + startUpdateTimerByLane(lane); scheduleUpdateOnFiber(root, fiber, lane); entangleTransitions(root, fiber, lane); } @@ -228,6 +230,7 @@ const classComponentUpdater = { const root = enqueueUpdate(fiber, update, lane); if (root !== null) { + startUpdateTimerByLane(lane); scheduleUpdateOnFiber(root, fiber, lane); entangleTransitions(root, fiber, lane); } @@ -262,6 +265,7 @@ const classComponentUpdater = { const root = enqueueUpdate(fiber, update, lane); if (root !== null) { + startUpdateTimerByLane(lane); 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 59d2f0f025610..77d3e985011de 100644 --- a/packages/react-reconciler/src/ReactFiberHooks.js +++ b/packages/react-reconciler/src/ReactFiberHooks.js @@ -131,6 +131,7 @@ import { markStateUpdateScheduled, setIsStrictModeForDevtools, } from './ReactFiberDevToolsHook'; +import {startUpdateTimerByLane} from './ReactProfilerTimer'; import {createCache} from './ReactFiberCacheComponent'; import { createUpdate as createLegacyQueueUpdate, @@ -3019,7 +3020,12 @@ function startTransition( dispatchOptimisticSetState(fiber, false, queue, pendingState); } else { ReactSharedInternals.T = null; - dispatchSetState(fiber, queue, pendingState); + dispatchSetStateInternal( + fiber, + queue, + pendingState, + requestUpdateLane(fiber), + ); ReactSharedInternals.T = currentTransition; } @@ -3062,13 +3068,28 @@ function startTransition( thenable, finishedState, ); - dispatchSetState(fiber, queue, (thenableForFinishedState: any)); + dispatchSetStateInternal( + fiber, + queue, + (thenableForFinishedState: any), + requestUpdateLane(fiber), + ); } else { - dispatchSetState(fiber, queue, finishedState); + dispatchSetStateInternal( + fiber, + queue, + finishedState, + requestUpdateLane(fiber), + ); } } else { // Async actions are not enabled. - dispatchSetState(fiber, queue, finishedState); + dispatchSetStateInternal( + fiber, + queue, + finishedState, + requestUpdateLane(fiber), + ); callback(); } } catch (error) { @@ -3081,7 +3102,12 @@ function startTransition( status: 'rejected', reason: error, }; - dispatchSetState(fiber, queue, rejectedThenable); + dispatchSetStateInternal( + fiber, + queue, + rejectedThenable, + requestUpdateLane(fiber), + ); } else { // The error rethrowing behavior is only enabled when the async actions // feature is on, even for sync actions. @@ -3253,7 +3279,12 @@ export function requestFormReset(formFiber: Fiber) { const newResetState = {}; const resetStateHook: Hook = (stateHook.next: any); const resetStateQueue = resetStateHook.queue; - dispatchSetState(formFiber, resetStateQueue, newResetState); + dispatchSetStateInternal( + formFiber, + resetStateQueue, + newResetState, + requestUpdateLane(formFiber), + ); } function mountTransition(): [ @@ -3385,6 +3416,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); scheduleUpdateOnFiber(root, provider, lane); entangleLegacyQueueTransitions(root, provider, lane); } @@ -3450,6 +3482,7 @@ function dispatchReducerAction( } else { const root = enqueueConcurrentHookUpdate(fiber, queue, update, lane); if (root !== null) { + startUpdateTimerByLane(lane); scheduleUpdateOnFiber(root, fiber, lane); entangleTransitionUpdate(root, queue, lane); } @@ -3474,7 +3507,24 @@ function dispatchSetState( } const lane = requestUpdateLane(fiber); + const didScheduleUpdate = dispatchSetStateInternal( + fiber, + queue, + action, + lane, + ); + if (didScheduleUpdate) { + startUpdateTimerByLane(lane); + } + markUpdateInDevTools(fiber, lane, action); +} +function dispatchSetStateInternal( + fiber: Fiber, + queue: UpdateQueue, + action: A, + lane: Lane, +): boolean { const update: Update = { lane, revertLane: NoLane, @@ -3518,7 +3568,7 @@ function dispatchSetState( // time the reducer has changed. // TODO: Do we still need to entangle transitions in this case? enqueueConcurrentHookUpdateAndEagerlyBailout(fiber, queue, update); - return; + return false; } } catch (error) { // Suppress the error. It will throw again in the render phase. @@ -3534,10 +3584,10 @@ function dispatchSetState( if (root !== null) { scheduleUpdateOnFiber(root, fiber, lane); entangleTransitionUpdate(root, queue, lane); + return true; } } - - markUpdateInDevTools(fiber, lane, action); + return false; } function dispatchOptimisticSetState( @@ -3619,6 +3669,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(SyncLane); scheduleUpdateOnFiber(root, fiber, SyncLane); // Optimistic updates are always synchronous, so we don't need to call // entangleTransitionUpdate here. diff --git a/packages/react-reconciler/src/ReactFiberLane.js b/packages/react-reconciler/src/ReactFiberLane.js index f72174e208555..b8c051def4eef 100644 --- a/packages/react-reconciler/src/ReactFiberLane.js +++ b/packages/react-reconciler/src/ReactFiberLane.js @@ -592,6 +592,10 @@ export function includesSyncLane(lanes: Lanes): boolean { return (lanes & (SyncLane | SyncHydrationLane)) !== NoLanes; } +export function isSyncLane(lanes: Lanes): boolean { + return (lanes & (SyncLane | SyncHydrationLane)) !== NoLanes; +} + export function includesNonIdleWork(lanes: Lanes): boolean { return (lanes & NonIdleLanes) !== NoLanes; } @@ -608,6 +612,10 @@ export function includesOnlyTransitions(lanes: Lanes): boolean { return (lanes & TransitionLanes) === lanes; } +export function includesTransitionLane(lanes: Lanes): boolean { + return (lanes & TransitionLanes) !== NoLanes; +} + export function includesBlockingLane(lanes: Lanes): boolean { const SyncDefaultLanes = InputContinuousHydrationLane | @@ -623,6 +631,15 @@ export function includesExpiredLane(root: FiberRoot, lanes: Lanes): boolean { return (lanes & root.expiredLanes) !== NoLanes; } +export function isBlockingLane(lane: Lane): boolean { + const SyncDefaultLanes = + InputContinuousHydrationLane | + InputContinuousLane | + DefaultHydrationLane | + DefaultLane; + return (lane & SyncDefaultLanes) !== NoLanes; +} + export function isTransitionLane(lane: Lane): boolean { return (lane & TransitionLanes) !== NoLanes; } diff --git a/packages/react-reconciler/src/ReactFiberPerformanceTrack.js b/packages/react-reconciler/src/ReactFiberPerformanceTrack.js index a053ea56ffc7f..94a7ec458fc57 100644 --- a/packages/react-reconciler/src/ReactFiberPerformanceTrack.js +++ b/packages/react-reconciler/src/ReactFiberPerformanceTrack.js @@ -99,3 +99,68 @@ export function logComponentEffect( performance.measure(name, reusableComponentOptions); } } + +export function logBlockingStart( + updateTime: number, + eventTime: number, + eventType: null | string, + renderStartTime: number, +): void { + if (supportsUserTiming) { + reusableComponentDevToolDetails.track = 'Blocking'; + if (eventTime > 0 && eventType !== null) { + // Log the time from the event timeStamp until we called setState. + reusableComponentDevToolDetails.color = 'secondary-dark'; + reusableComponentOptions.start = eventTime; + reusableComponentOptions.end = + updateTime > 0 ? updateTime : renderStartTime; + performance.measure(eventType, reusableComponentOptions); + } + if (updateTime > 0) { + // Log the time from when we called setState until we started rendering. + reusableComponentDevToolDetails.color = 'primary-light'; + reusableComponentOptions.start = updateTime; + reusableComponentOptions.end = renderStartTime; + performance.measure('Blocked', reusableComponentOptions); + } + } +} + +export function logTransitionStart( + startTime: number, + updateTime: number, + eventTime: number, + eventType: null | string, + renderStartTime: number, +): void { + if (supportsUserTiming) { + reusableComponentDevToolDetails.track = 'Transition'; + if (eventTime > 0 && eventType !== null) { + // Log the time from the event timeStamp until we started a transition. + reusableComponentDevToolDetails.color = 'secondary-dark'; + reusableComponentOptions.start = eventTime; + reusableComponentOptions.end = + startTime > 0 + ? startTime + : updateTime > 0 + ? updateTime + : renderStartTime; + performance.measure(eventType, reusableComponentOptions); + } + if (startTime > 0) { + // Log the time from when we started an async transition until we called setState or started rendering. + reusableComponentDevToolDetails.color = 'primary-dark'; + reusableComponentOptions.start = startTime; + reusableComponentOptions.end = + updateTime > 0 ? updateTime : renderStartTime; + performance.measure('Action', reusableComponentOptions); + } + if (updateTime > 0) { + // Log the time from when we called setState until we started rendering. + reusableComponentDevToolDetails.color = 'primary-light'; + reusableComponentOptions.start = updateTime; + reusableComponentOptions.end = renderStartTime; + performance.measure('Blocked', reusableComponentOptions); + } + } +} diff --git a/packages/react-reconciler/src/ReactFiberReconciler.js b/packages/react-reconciler/src/ReactFiberReconciler.js index 9a200b4e4feb4..94f1397eb129e 100644 --- a/packages/react-reconciler/src/ReactFiberReconciler.js +++ b/packages/react-reconciler/src/ReactFiberReconciler.js @@ -61,6 +61,7 @@ import { onScheduleRoot, injectProfilingHooks, } from './ReactFiberDevToolsHook'; +import {startUpdateTimerByLane} from './ReactProfilerTimer'; import { requestUpdateLane, scheduleUpdateOnFiber, @@ -433,6 +434,7 @@ function updateContainerImpl( const root = enqueueUpdate(rootFiber, update, lane); if (root !== null) { + startUpdateTimerByLane(lane); scheduleUpdateOnFiber(root, rootFiber, lane); entangleTransitions(root, rootFiber, lane); } diff --git a/packages/react-reconciler/src/ReactFiberTransition.js b/packages/react-reconciler/src/ReactFiberTransition.js index c378beee30d3b..8ddd7083363a8 100644 --- a/packages/react-reconciler/src/ReactFiberTransition.js +++ b/packages/react-reconciler/src/ReactFiberTransition.js @@ -35,6 +35,7 @@ import { import ReactSharedInternals from 'shared/ReactSharedInternals'; import {entangleAsyncAction} from './ReactFiberAsyncAction'; +import {startAsyncTransitionTimer} from './ReactProfilerTimer'; export const NoTransition = null; @@ -69,6 +70,13 @@ ReactSharedInternals.S = function onStartTransitionFinishForReconciler( returnValue !== null && typeof returnValue.then === 'function' ) { + // If we're going to wait on some async work before scheduling an update. + // We mark the time so we can later log how long we were blocked on the Action. + // Ideally, we'd include the sync part of the action too but since that starts + // in isomorphic code it currently leads to tricky layering. We'd have to pass + // in performance.now() to this callback but we sometimes use a polyfill. + startAsyncTransitionTimer(); + // This is an async action const thenable: Thenable = (returnValue: any); entangleAsyncAction(transition, thenable); diff --git a/packages/react-reconciler/src/ReactFiberWorkLoop.js b/packages/react-reconciler/src/ReactFiberWorkLoop.js index dba089e81f3e0..b576309dc84ab 100644 --- a/packages/react-reconciler/src/ReactFiberWorkLoop.js +++ b/packages/react-reconciler/src/ReactFiberWorkLoop.js @@ -68,6 +68,10 @@ import { logRenderStarted, logRenderStopped, } from './DebugTracing'; +import { + logBlockingStart, + logTransitionStart, +} from './ReactFiberPerformanceTrack'; import { resetAfterCommit, @@ -145,6 +149,7 @@ import { includesOnlyRetries, includesOnlyTransitions, includesBlockingLane, + includesTransitionLane, includesExpiredLane, getNextLanes, getEntangledLanes, @@ -221,7 +226,20 @@ import { } from './ReactFiberConcurrentUpdates'; import { + blockingUpdateTime, + blockingEventTime, + blockingEventType, + transitionStartTime, + transitionUpdateTime, + transitionEventTime, + transitionEventType, + clearBlockingTimers, + clearTransitionTimers, + clampBlockingTimers, + clampTransitionTimers, markNestedUpdateScheduled, + renderStartTime, + recordRenderTime, recordCompleteTime, recordCommitTime, resetNestedUpdateFlag, @@ -1698,7 +1716,48 @@ function resetWorkInProgressStack() { workInProgress = null; } +function finalizeRender(lanes: Lanes, finalizationTime: number): void { + if (enableProfilerTimer && enableComponentPerformanceTrack) { + if (includesSyncLane(lanes) || includesBlockingLane(lanes)) { + clampBlockingTimers(finalizationTime); + } + if (includesTransitionLane(lanes)) { + clampTransitionTimers(finalizationTime); + } + } +} + function prepareFreshStack(root: FiberRoot, lanes: Lanes): Fiber { + if (enableProfilerTimer && enableComponentPerformanceTrack) { + // Starting a new render. Log the end of any previous renders and the + // blocked time before the render started. + recordRenderTime(); + // If this was a restart, e.g. due to an interrupting update, then there's no space + // in the track to log the cause since we'll have rendered all the way up until the + // restart so we need to clamp that. + finalizeRender(workInProgressRootRenderLanes, renderStartTime); + + if (includesSyncLane(lanes) || includesBlockingLane(lanes)) { + logBlockingStart( + blockingUpdateTime, + blockingEventTime, + blockingEventType, + renderStartTime, + ); + clearBlockingTimers(); + } + if (includesTransitionLane(lanes)) { + logTransitionStart( + transitionStartTime, + transitionUpdateTime, + transitionEventTime, + transitionEventType, + renderStartTime, + ); + clearTransitionTimers(); + } + } + root.finishedWork = null; root.finishedLanes = NoLanes; @@ -2240,6 +2299,7 @@ function renderRootConcurrent(root: FiberRoot, lanes: Lanes) { } workInProgressTransitions = getTransitionsForLanes(root, lanes); + resetRenderTimer(); prepareFreshStack(root, lanes); } else { @@ -3358,6 +3418,12 @@ function commitRootImpl( nestedUpdateCount = 0; } + if (enableProfilerTimer && enableComponentPerformanceTrack) { + if (!rootDidHavePassiveEffects) { + finalizeRender(lanes, now()); + } + } + // If layout work was scheduled, flush it now. flushSyncWorkOnAllRoots(); @@ -3539,6 +3605,10 @@ function flushPassiveEffectsImpl() { executionContext = prevExecutionContext; + if (enableProfilerTimer && enableComponentPerformanceTrack) { + finalizeRender(lanes, now()); + } + flushSyncWorkOnAllRoots(); if (enableTransitionTracing) { diff --git a/packages/react-reconciler/src/ReactProfilerTimer.js b/packages/react-reconciler/src/ReactProfilerTimer.js index d65ca0a7544ee..cf3133524813e 100644 --- a/packages/react-reconciler/src/ReactProfilerTimer.js +++ b/packages/react-reconciler/src/ReactProfilerTimer.js @@ -9,10 +9,16 @@ import type {Fiber} from './ReactInternalTypes'; +import type {Lane} from './ReactFiberLane'; +import {isTransitionLane, isBlockingLane, isSyncLane} from './ReactFiberLane'; + +import {resolveEventType, resolveEventTimeStamp} from './ReactFiberConfig'; + import { enableProfilerCommitHooks, enableProfilerNestedUpdatePhase, enableProfilerTimer, + enableComponentPerformanceTrack, } from 'shared/ReactFeatureFlags'; // Intentionally not named imports because Rollup would use dynamic dispatch for @@ -21,6 +27,7 @@ import * as Scheduler from 'scheduler'; const {unstable_now: now} = Scheduler; +export let renderStartTime: number = -0; export let completeTime: number = -0; export let commitTime: number = -0; export let profilerStartTime: number = -1.1; @@ -29,6 +36,111 @@ export let componentEffectDuration: number = -0; export let componentEffectStartTime: number = -1.1; export let componentEffectEndTime: number = -1.1; +export let blockingUpdateTime: number = -1.1; // First sync setState scheduled. +export let blockingEventTime: number = -1.1; // Event timeStamp of the first setState. +export let blockingEventType: null | string = null; // Event type of the first setState. +// TODO: This should really be one per Transition lane. +export let transitionStartTime: number = -1.1; // First startTransition call before setState. +export let transitionUpdateTime: number = -1.1; // First transition setState scheduled. +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 function startUpdateTimerByLane(lane: Lane): void { + if (!enableProfilerTimer || !enableComponentPerformanceTrack) { + return; + } + if (isSyncLane(lane) || isBlockingLane(lane)) { + if (blockingUpdateTime < 0) { + blockingUpdateTime = now(); + blockingEventTime = resolveEventTimeStamp(); + blockingEventType = resolveEventType(); + } + } else if (isTransitionLane(lane)) { + if (transitionUpdateTime < 0) { + transitionUpdateTime = now(); + if (transitionStartTime < 0) { + transitionEventTime = resolveEventTimeStamp(); + transitionEventType = resolveEventType(); + } + } + } +} + +export function clearBlockingTimers(): void { + blockingUpdateTime = -1.1; +} + +export function startAsyncTransitionTimer(): void { + if (!enableProfilerTimer || !enableComponentPerformanceTrack) { + return; + } + if (transitionStartTime < 0 && transitionUpdateTime < 0) { + transitionStartTime = now(); + transitionEventTime = resolveEventTimeStamp(); + transitionEventType = resolveEventType(); + } +} + +export function hasScheduledTransitionWork(): boolean { + // If we have setState on a transition or scheduled useActionState update. + return transitionUpdateTime > -1; +} + +// We use this marker to indicate that we have scheduled a render to be performed +// but it's not an explicit state update. +const ACTION_STATE_MARKER = -0.5; + +export function startActionStateUpdate(): void { + if (!enableProfilerTimer || !enableComponentPerformanceTrack) { + return; + } + if (transitionUpdateTime < 0) { + transitionUpdateTime = ACTION_STATE_MARKER; + } +} + +export function clearAsyncTransitionTimer(): void { + transitionStartTime = -1.1; +} + +export function clearTransitionTimers(): void { + transitionStartTime = -1.1; + transitionUpdateTime = -1.1; +} + +export function clampBlockingTimers(finalTime: number): void { + if (!enableProfilerTimer || !enableComponentPerformanceTrack) { + return; + } + // If we had new updates come in while we were still rendering or committing, we don't want + // those update times to create overlapping tracks in the performance timeline so we clamp + // them to the end of the commit phase. + if (blockingUpdateTime >= 0 && blockingUpdateTime < finalTime) { + blockingUpdateTime = finalTime; + } + if (blockingEventTime >= 0 && blockingEventTime < finalTime) { + blockingEventTime = finalTime; + } +} + +export function clampTransitionTimers(finalTime: number): void { + if (!enableProfilerTimer || !enableComponentPerformanceTrack) { + return; + } + // If we had new updates come in while we were still rendering or committing, we don't want + // those update times to create overlapping tracks in the performance timeline so we clamp + // them to the end of the commit phase. + if (transitionStartTime >= 0 && transitionStartTime < finalTime) { + transitionStartTime = finalTime; + } + if (transitionUpdateTime >= 0 && transitionUpdateTime < finalTime) { + transitionUpdateTime = finalTime; + } + if (transitionEventTime >= 0 && transitionEventTime < finalTime) { + transitionEventTime = finalTime; + } +} + export function pushNestedEffectDurations(): number { if (!enableProfilerTimer || !enableProfilerCommitHooks) { return 0; @@ -136,6 +248,13 @@ export function syncNestedUpdateFlag(): void { } } +export function recordRenderTime(): void { + if (!enableProfilerTimer || !enableComponentPerformanceTrack) { + return; + } + renderStartTime = now(); +} + export function recordCompleteTime(): void { if (!enableProfilerTimer) { return; diff --git a/packages/react-reconciler/src/__tests__/ReactFiberHostContext-test.internal.js b/packages/react-reconciler/src/__tests__/ReactFiberHostContext-test.internal.js index 753c2d849b19a..60726514474fb 100644 --- a/packages/react-reconciler/src/__tests__/ReactFiberHostContext-test.internal.js +++ b/packages/react-reconciler/src/__tests__/ReactFiberHostContext-test.internal.js @@ -83,6 +83,12 @@ describe('ReactFiberHostContext', () => { } return DefaultEventPriority; }, + resolveEventType: function () { + return null; + }, + resolveEventTimeStamp: function () { + return -1.1; + }, shouldAttemptEagerTransition() { return false; }, diff --git a/packages/react-reconciler/src/forks/ReactFiberConfig.custom.js b/packages/react-reconciler/src/forks/ReactFiberConfig.custom.js index 0826f9d95ee0d..1f525d9a05c52 100644 --- a/packages/react-reconciler/src/forks/ReactFiberConfig.custom.js +++ b/packages/react-reconciler/src/forks/ReactFiberConfig.custom.js @@ -73,6 +73,8 @@ export const getInstanceFromScope = $$$config.getInstanceFromScope; export const setCurrentUpdatePriority = $$$config.setCurrentUpdatePriority; export const getCurrentUpdatePriority = $$$config.getCurrentUpdatePriority; export const resolveUpdatePriority = $$$config.resolveUpdatePriority; +export const resolveEventType = $$$config.resolveEventType; +export const resolveEventTimeStamp = $$$config.resolveEventTimeStamp; export const shouldAttemptEagerTransition = $$$config.shouldAttemptEagerTransition; export const detachDeletedInstance = $$$config.detachDeletedInstance; diff --git a/packages/react-test-renderer/src/ReactFiberConfigTestHost.js b/packages/react-test-renderer/src/ReactFiberConfigTestHost.js index 9d62e8a19ccf2..cb38a985eb800 100644 --- a/packages/react-test-renderer/src/ReactFiberConfigTestHost.js +++ b/packages/react-test-renderer/src/ReactFiberConfigTestHost.js @@ -224,6 +224,13 @@ export function resolveUpdatePriority(): EventPriority { } return DefaultEventPriority; } +export function resolveEventType(): null | string { + return null; +} + +export function resolveEventTimeStamp(): number { + return -1.1; +} export function shouldAttemptEagerTransition(): boolean { return false; } diff --git a/packages/react/src/__tests__/ReactProfiler-test.internal.js b/packages/react/src/__tests__/ReactProfiler-test.internal.js index 0d7aead65f81d..14aacca63a7ca 100644 --- a/packages/react/src/__tests__/ReactProfiler-test.internal.js +++ b/packages/react/src/__tests__/ReactProfiler-test.internal.js @@ -178,6 +178,9 @@ describe(`onRender`, () => { 'read current time', 'read current time', 'read current time', + 'read current time', + 'read current time', + 'read current time', ]); } else { assertLog([ @@ -212,6 +215,9 @@ describe(`onRender`, () => { 'read current time', 'read current time', 'read current time', + 'read current time', + 'read current time', + 'read current time', ]); } else { assertLog([