diff --git a/packages/react-reconciler/src/ReactFiberPerformanceTrack.js b/packages/react-reconciler/src/ReactFiberPerformanceTrack.js index 86f96d5d079aa..92ca7e00e2696 100644 --- a/packages/react-reconciler/src/ReactFiberPerformanceTrack.js +++ b/packages/react-reconciler/src/ReactFiberPerformanceTrack.js @@ -636,11 +636,25 @@ export function logBlockingStart( ): void { if (supportsUserTiming) { currentTrack = 'Blocking'; + // Clamp start times + if (updateTime > 0) { + if (updateTime > renderStartTime) { + updateTime = renderStartTime; + } + } else { + updateTime = renderStartTime; + } + if (eventTime > 0) { + if (eventTime > updateTime) { + eventTime = updateTime; + } + } else { + eventTime = updateTime; + } // 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. - const eventEndTime = updateTime > 0 ? updateTime : renderStartTime; - if (eventTime > 0 && eventType !== null && eventEndTime > eventTime) { + if (eventType !== null && updateTime > eventTime) { // Log the time from the event timeStamp until we called setState. const color = eventIsRepeat ? 'secondary-light' : 'warning'; if (__DEV__ && debugTask) { @@ -648,9 +662,9 @@ export function logBlockingStart( // $FlowFixMe[method-unbinding] console.timeStamp.bind( console, - eventIsRepeat ? '' : 'Event: ' + eventType, + eventIsRepeat ? 'Consecutive' : 'Event: ' + eventType, eventTime, - eventEndTime, + updateTime, currentTrack, LANES_TRACK_GROUP, color, @@ -658,16 +672,16 @@ export function logBlockingStart( ); } else { console.timeStamp( - eventIsRepeat ? '' : 'Event: ' + eventType, + eventIsRepeat ? 'Consecutive' : 'Event: ' + eventType, eventTime, - eventEndTime, + updateTime, currentTrack, LANES_TRACK_GROUP, color, ); } } - if (updateTime > 0 && renderStartTime > updateTime) { + if (renderStartTime > updateTime) { // Log the time from when we called setState until we started rendering. const color = isSpawnedUpdate ? 'error' @@ -739,18 +753,39 @@ export function logTransitionStart( ): void { if (supportsUserTiming) { currentTrack = 'Transition'; - const eventEndTime = - startTime > 0 ? startTime : updateTime > 0 ? updateTime : renderStartTime; - if (eventTime > 0 && eventEndTime > eventTime && eventType !== null) { + // Clamp start times + if (updateTime > 0) { + if (updateTime > renderStartTime) { + updateTime = renderStartTime; + } + } else { + updateTime = renderStartTime; + } + if (startTime > 0) { + if (startTime > updateTime) { + startTime = updateTime; + } + } else { + startTime = updateTime; + } + if (eventTime > 0) { + if (eventTime > startTime) { + eventTime = startTime; + } + } else { + eventTime = startTime; + } + + if (startTime > eventTime && eventType !== null) { // Log the time from the event timeStamp until we started a transition. const color = eventIsRepeat ? 'secondary-light' : 'warning'; if (__DEV__ && debugTask) { debugTask.run( console.timeStamp.bind( console, - eventIsRepeat ? '' : 'Event: ' + eventType, + eventIsRepeat ? 'Consecutive' : 'Event: ' + eventType, eventTime, - eventEndTime, + startTime, currentTrack, LANES_TRACK_GROUP, color, @@ -758,17 +793,16 @@ export function logTransitionStart( ); } else { console.timeStamp( - eventIsRepeat ? '' : 'Event: ' + eventType, + eventIsRepeat ? 'Consecutive' : 'Event: ' + eventType, eventTime, - eventEndTime, + startTime, currentTrack, LANES_TRACK_GROUP, color, ); } } - const startEndTime = updateTime > 0 ? updateTime : renderStartTime; - if (startTime > 0 && startEndTime > startTime) { + if (updateTime > startTime) { // Log the time from when we started an async transition until we called setState or started rendering. // TODO: Ideally this would use the debugTask of the startTransition call perhaps. if (__DEV__ && debugTask) { @@ -778,7 +812,7 @@ export function logTransitionStart( console, 'Action', startTime, - startEndTime, + updateTime, currentTrack, LANES_TRACK_GROUP, 'primary-dark', @@ -788,14 +822,14 @@ export function logTransitionStart( console.timeStamp( 'Action', startTime, - startEndTime, + updateTime, currentTrack, LANES_TRACK_GROUP, 'primary-dark', ); } } - if (updateTime > 0 && renderStartTime > updateTime) { + if (renderStartTime > updateTime) { // Log the time from when we called setState until we started rendering. const label = isPingedUpdate ? 'Promise Resolved' @@ -1286,6 +1320,7 @@ export function logCommitPhase( startTime: number, endTime: number, errors: null | Array>, + abortedViewTransition: boolean, debugTask: null | ConsoleTask, ): void { if (errors !== null) { @@ -1301,22 +1336,24 @@ export function logCommitPhase( // $FlowFixMe[method-unbinding] console.timeStamp.bind( console, - 'Commit', + abortedViewTransition + ? 'Commit Interrupted View Transition' + : 'Commit', startTime, endTime, currentTrack, LANES_TRACK_GROUP, - 'secondary-dark', + abortedViewTransition ? 'error' : 'secondary-dark', ), ); } else { console.timeStamp( - 'Commit', + abortedViewTransition ? 'Commit Interrupted View Transition' : 'Commit', startTime, endTime, currentTrack, LANES_TRACK_GROUP, - 'secondary-dark', + abortedViewTransition ? 'error' : 'secondary-dark', ); } } @@ -1337,7 +1374,7 @@ export function logPaintYieldPhase( // $FlowFixMe[method-unbinding] console.timeStamp.bind( console, - delayedUntilPaint ? 'Waiting for Paint' : '', + delayedUntilPaint ? 'Waiting for Paint' : 'Waiting', startTime, endTime, currentTrack, @@ -1347,7 +1384,7 @@ export function logPaintYieldPhase( ); } else { console.timeStamp( - delayedUntilPaint ? 'Waiting for Paint' : '', + delayedUntilPaint ? 'Waiting for Paint' : 'Waiting', startTime, endTime, currentTrack, @@ -1358,6 +1395,81 @@ export function logPaintYieldPhase( } } +export function logStartViewTransitionYieldPhase( + startTime: number, + endTime: number, + abortedViewTransition: boolean, + debugTask: null | ConsoleTask, +): void { + if (supportsUserTiming) { + if (endTime <= startTime) { + return; + } + if (__DEV__ && debugTask) { + debugTask.run( + // $FlowFixMe[method-unbinding] + console.timeStamp.bind( + console, + abortedViewTransition + ? 'Interrupted View Transition' + : 'Starting Animation', + startTime, + endTime, + currentTrack, + LANES_TRACK_GROUP, + abortedViewTransition ? 'error' : 'secondary-light', + ), + ); + } else { + console.timeStamp( + abortedViewTransition + ? 'Interrupted View Transition' + : 'Starting Animation', + startTime, + endTime, + currentTrack, + LANES_TRACK_GROUP, + abortedViewTransition ? ' error' : 'secondary-light', + ); + } + } +} + +export function logAnimatingPhase( + startTime: number, + endTime: number, + debugTask: null | ConsoleTask, +): void { + if (supportsUserTiming) { + if (endTime <= startTime) { + return; + } + if (__DEV__ && debugTask) { + debugTask.run( + // $FlowFixMe[method-unbinding] + console.timeStamp.bind( + console, + 'Animating', + startTime, + endTime, + currentTrack, + LANES_TRACK_GROUP, + 'secondary', + ), + ); + } else { + console.timeStamp( + 'Animating', + startTime, + endTime, + currentTrack, + LANES_TRACK_GROUP, + 'secondary', + ); + } + } +} + export function logPassiveCommitPhase( startTime: number, endTime: number, diff --git a/packages/react-reconciler/src/ReactFiberRootScheduler.js b/packages/react-reconciler/src/ReactFiberRootScheduler.js index 3ed7ad7e2803a..26b6255227626 100644 --- a/packages/react-reconciler/src/ReactFiberRootScheduler.js +++ b/packages/react-reconciler/src/ReactFiberRootScheduler.js @@ -41,6 +41,7 @@ import { NoContext, RenderContext, flushPendingEffects, + flushPendingEffectsDelayed, getExecutionContext, getWorkInProgressRoot, getWorkInProgressRootRenderLanes, @@ -542,7 +543,7 @@ function performWorkOnRootViaSchedulerTask( // Flush any pending passive effects before deciding which lanes to work on, // in case they schedule additional work. const originalCallbackNode = root.callbackNode; - const didFlushPassiveEffects = flushPendingEffects(true); + const didFlushPassiveEffects = flushPendingEffectsDelayed(); if (didFlushPassiveEffects) { // Something in the passive effect phase may have canceled the current task. // Check if the task node for this root was changed. diff --git a/packages/react-reconciler/src/ReactFiberWorkLoop.js b/packages/react-reconciler/src/ReactFiberWorkLoop.js index 79909cc25f104..d141c2855f66e 100644 --- a/packages/react-reconciler/src/ReactFiberWorkLoop.js +++ b/packages/react-reconciler/src/ReactFiberWorkLoop.js @@ -83,6 +83,8 @@ import { logSuspendedCommitPhase, logCommitPhase, logPaintYieldPhase, + logStartViewTransitionYieldPhase, + logAnimatingPhase, logPassiveCommitPhase, logYieldTime, logActionYieldTime, @@ -674,6 +676,11 @@ const IMMEDIATE_COMMIT = 0; const SUSPENDED_COMMIT = 1; const THROTTLED_COMMIT = 2; +type DelayedCommitReason = 0 | 1 | 2 | 3; +const ABORTED_VIEW_TRANSITION_COMMIT = 1; +const DELAYED_PASSIVE_COMMIT = 2; +const ANIMATION_STARTED_COMMIT = 3; + const NO_PENDING_EFFECTS = 0; const PENDING_MUTATION_PHASE = 1; const PENDING_LAYOUT_PHASE = 2; @@ -696,6 +703,7 @@ let pendingViewTransitionEvents: Array<(types: Array) => void> | null = let pendingTransitionTypes: null | TransitionTypes = null; let pendingDidIncludeRenderPhaseUpdate: boolean = false; let pendingSuspendedCommitReason: SuspendedCommitReason = IMMEDIATE_COMMIT; // Profiling-only +let pendingDelayedCommitReason: DelayedCommitReason = IMMEDIATE_COMMIT; // Profiling-only // Use these to prevent an infinite loop of nested updates const NESTED_UPDATE_LIMIT = 50; @@ -3436,6 +3444,7 @@ function commitRoot( if (enableProfilerTimer) { pendingEffectsRenderEndTime = completedRenderEndTime; pendingSuspendedCommitReason = suspendedCommitReason; + pendingDelayedCommitReason = IMMEDIATE_COMMIT; } if (enableGestureTransition && isGestureRender(lanes)) { @@ -3495,7 +3504,10 @@ function commitRoot( // event when logging events. trackSchedulerEvent(); } - flushPassiveEffects(true); + if (pendingDelayedCommitReason === IMMEDIATE_COMMIT) { + pendingDelayedCommitReason = DELAYED_PASSIVE_COMMIT; + } + flushPassiveEffects(); // This render triggered passive effects: release the root cache pool // *after* passive effects fire to avoid freeing a cache pool that may // be referenced by a node in the tree (HostRoot, Cache boundary etc) @@ -3736,6 +3748,23 @@ function flushLayoutEffects(): void { ReactSharedInternals.T = prevTransition; } } + + const completedRenderEndTime = pendingEffectsRenderEndTime; + const suspendedCommitReason = pendingSuspendedCommitReason; + + if (enableProfilerTimer && enableComponentPerformanceTrack) { + recordCommitEndTime(); + logCommitPhase( + suspendedCommitReason === IMMEDIATE_COMMIT + ? completedRenderEndTime + : commitStartTime, + commitEndTime, + commitErrors, + pendingDelayedCommitReason === ABORTED_VIEW_TRANSITION_COMMIT, + workInProgressUpdateTask, + ); + } + pendingEffectsStatus = PENDING_AFTER_MUTATION_PHASE; } @@ -3748,6 +3777,25 @@ function flushSpawnedWork(): void { ) { return; } + if (enableProfilerTimer && enableComponentPerformanceTrack) { + // If we didn't skip the after mutation phase, when is means we started an animation. + const startedAnimation = pendingEffectsStatus === PENDING_SPAWNED_WORK; + if (startedAnimation) { + const startViewTransitionStartTime = commitEndTime; + // Update the new commitEndTime to when we started the animation. + recordCommitEndTime(); + logStartViewTransitionYieldPhase( + startViewTransitionStartTime, + commitEndTime, + pendingDelayedCommitReason === ABORTED_VIEW_TRANSITION_COMMIT, + workInProgressUpdateTask, // TODO: Use a ViewTransition Task. + ); + if (pendingDelayedCommitReason !== ABORTED_VIEW_TRANSITION_COMMIT) { + pendingDelayedCommitReason = ANIMATION_STARTED_COMMIT; + } + } + } + pendingEffectsStatus = NO_PENDING_EFFECTS; pendingViewTransition = null; // The view transition has now fully started. @@ -3759,22 +3807,8 @@ function flushSpawnedWork(): void { const root = pendingEffectsRoot; const finishedWork = pendingFinishedWork; const lanes = pendingEffectsLanes; - const completedRenderEndTime = pendingEffectsRenderEndTime; const recoverableErrors = pendingRecoverableErrors; const didIncludeRenderPhaseUpdate = pendingDidIncludeRenderPhaseUpdate; - const suspendedCommitReason = pendingSuspendedCommitReason; - - if (enableProfilerTimer && enableComponentPerformanceTrack) { - recordCommitEndTime(); - logCommitPhase( - suspendedCommitReason === IMMEDIATE_COMMIT - ? completedRenderEndTime - : commitStartTime, - commitEndTime, - commitErrors, - workInProgressUpdateTask, - ); - } const passiveSubtreeMask = enableViewTransition && includesOnlyViewTransitionEligibleLanes(lanes) @@ -4141,7 +4175,14 @@ function releaseRootPooledCache(root: FiberRoot, remainingLanes: Lanes) { let didWarnAboutInterruptedViewTransitions = false; -export function flushPendingEffects(wasDelayedCommit?: boolean): boolean { +export function flushPendingEffectsDelayed(): boolean { + if (pendingDelayedCommitReason === IMMEDIATE_COMMIT) { + pendingDelayedCommitReason = DELAYED_PASSIVE_COMMIT; + } + return flushPendingEffects(); +} + +export function flushPendingEffects(): boolean { // Returns whether passive effects were flushed. if (enableViewTransition && pendingViewTransition !== null) { // If we forced a flush before the View Transition full started then we skip it. @@ -4159,6 +4200,7 @@ export function flushPendingEffects(wasDelayedCommit?: boolean): boolean { } } pendingViewTransition = null; + pendingDelayedCommitReason = ABORTED_VIEW_TRANSITION_COMMIT; } flushGestureMutations(); flushGestureAnimations(); @@ -4166,10 +4208,10 @@ export function flushPendingEffects(wasDelayedCommit?: boolean): boolean { flushLayoutEffects(); // Skip flushAfterMutation if we're forcing this early. flushSpawnedWork(); - return flushPassiveEffects(wasDelayedCommit); + return flushPassiveEffects(); } -function flushPassiveEffects(wasDelayedCommit?: boolean): boolean { +function flushPassiveEffects(): boolean { if (pendingEffectsStatus !== PENDING_PASSIVE_PHASE) { return false; } @@ -4194,7 +4236,7 @@ function flushPassiveEffects(wasDelayedCommit?: boolean): boolean { try { setCurrentUpdatePriority(priority); ReactSharedInternals.T = null; - return flushPassiveEffectsImpl(wasDelayedCommit); + return flushPassiveEffectsImpl(); } finally { setCurrentUpdatePriority(previousPriority); ReactSharedInternals.T = prevTransition; @@ -4206,7 +4248,7 @@ function flushPassiveEffects(wasDelayedCommit?: boolean): boolean { } } -function flushPassiveEffectsImpl(wasDelayedCommit: void | boolean) { +function flushPassiveEffectsImpl() { // Cache and clear the transitions flag const transitions = pendingPassiveTransitions; pendingPassiveTransitions = null; @@ -4246,12 +4288,21 @@ function flushPassiveEffectsImpl(wasDelayedCommit: void | boolean) { if (enableProfilerTimer && enableComponentPerformanceTrack) { resetCommitErrors(); passiveEffectStartTime = now(); - logPaintYieldPhase( - commitEndTime, - passiveEffectStartTime, - !!wasDelayedCommit, - workInProgressUpdateTask, - ); + if (pendingDelayedCommitReason === ANIMATION_STARTED_COMMIT) { + // The animation was started, so we've been animating since that happened. + logAnimatingPhase( + commitEndTime, + passiveEffectStartTime, + workInProgressUpdateTask, // TODO: Use a ViewTransition Task + ); + } else { + logPaintYieldPhase( + commitEndTime, + passiveEffectStartTime, + pendingDelayedCommitReason === DELAYED_PASSIVE_COMMIT, + workInProgressUpdateTask, + ); + } } if (enableSchedulingProfiler) { diff --git a/packages/react-reconciler/src/ReactProfilerTimer.js b/packages/react-reconciler/src/ReactProfilerTimer.js index a1779235fc02b..62b76ee6a407a 100644 --- a/packages/react-reconciler/src/ReactProfilerTimer.js +++ b/packages/react-reconciler/src/ReactProfilerTimer.js @@ -246,6 +246,7 @@ export function clearBlockingTimers(): void { blockingUpdateComponentName = null; blockingSuspendedTime = -1.1; blockingEventIsRepeat = true; + blockingClampTime = now(); } export function startAsyncTransitionTimer(): void { @@ -282,6 +283,7 @@ export function clearTransitionTimers(): void { transitionUpdateType = 0; transitionSuspendedTime = -1.1; transitionEventIsRepeat = true; + transitionClampTime = now(); } export function clampBlockingTimers(finalTime: number): void { diff --git a/packages/react/src/__tests__/ReactProfiler-test.internal.js b/packages/react/src/__tests__/ReactProfiler-test.internal.js index a8c00b2b562dc..ee1ec514e4d47 100644 --- a/packages/react/src/__tests__/ReactProfiler-test.internal.js +++ b/packages/react/src/__tests__/ReactProfiler-test.internal.js @@ -179,6 +179,7 @@ describe(`onRender`, () => { 'read current time', 'read current time', 'read current time', + 'read current time', ]); } else { assertLog([