From 4e9540e3c2a8f9ae56318b967939c99b3a815190 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Sebastian=20Markb=C3=A5ge?= Date: Mon, 23 Sep 2024 14:09:48 -0400 Subject: [PATCH] [Fiber] Log the Render/Commit phases and the gaps in between (#31016) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A slight behavior change here too is that I now mark the start of the commit phase before the BeforeMutationEffect phase. This affects `` too. The named sequences are as follows: Render -> Suspended or Throttled -> Commit -> Waiting for Paint -> Remaining Effects The Suspended phase is only logged if we delay the Commit due to CSS / images. The Throttled phase is only logged if we delay the commit due to the Suspense throttling timer. Screenshot 2024-09-20 at 9 14 23 PM I don't yet log render phases that don't complete. I think I also need to special case renders that or don't commit after being suspended. --- .../src/ReactFiberCommitEffects.js | 22 ++-- .../src/ReactFiberCommitWork.js | 12 +- .../src/ReactFiberPerformanceTrack.js | 65 ++++++++++ .../src/ReactFiberWorkLoop.js | 115 ++++++++++++++---- .../src/ReactProfilerTimer.js | 12 +- .../__tests__/ReactProfiler-test.internal.js | 2 + 6 files changed, 184 insertions(+), 44 deletions(-) diff --git a/packages/react-reconciler/src/ReactFiberCommitEffects.js b/packages/react-reconciler/src/ReactFiberCommitEffects.js index 8b1d4ceb6f9bb..4d10c9ee6faff 100644 --- a/packages/react-reconciler/src/ReactFiberCommitEffects.js +++ b/packages/react-reconciler/src/ReactFiberCommitEffects.js @@ -899,7 +899,7 @@ function safelyCallDestroy( function commitProfiler( finishedWork: Fiber, current: Fiber | null, - commitTime: number, + commitStartTime: number, effectDuration: number, ) { const {id, onCommit, onRender} = finishedWork.memoizedProps; @@ -918,7 +918,7 @@ function commitProfiler( finishedWork.actualDuration, finishedWork.treeBaseDuration, finishedWork.actualStartTime, - commitTime, + commitStartTime, ); } @@ -928,7 +928,7 @@ function commitProfiler( finishedWork.memoizedProps.id, phase, effectDuration, - commitTime, + commitStartTime, ); } } @@ -937,7 +937,7 @@ function commitProfiler( export function commitProfilerUpdate( finishedWork: Fiber, current: Fiber | null, - commitTime: number, + commitStartTime: number, effectDuration: number, ) { if (enableProfilerTimer) { @@ -948,11 +948,11 @@ export function commitProfilerUpdate( commitProfiler, finishedWork, current, - commitTime, + commitStartTime, effectDuration, ); } else { - commitProfiler(finishedWork, current, commitTime, effectDuration); + commitProfiler(finishedWork, current, commitStartTime, effectDuration); } } catch (error) { captureCommitPhaseError(finishedWork, finishedWork.return, error); @@ -963,7 +963,7 @@ export function commitProfilerUpdate( function commitProfilerPostCommitImpl( finishedWork: Fiber, current: Fiber | null, - commitTime: number, + commitStartTime: number, passiveEffectDuration: number, ): void { const {id, onPostCommit} = finishedWork.memoizedProps; @@ -976,14 +976,14 @@ function commitProfilerPostCommitImpl( } if (typeof onPostCommit === 'function') { - onPostCommit(id, phase, passiveEffectDuration, commitTime); + onPostCommit(id, phase, passiveEffectDuration, commitStartTime); } } export function commitProfilerPostCommit( finishedWork: Fiber, current: Fiber | null, - commitTime: number, + commitStartTime: number, passiveEffectDuration: number, ) { try { @@ -993,14 +993,14 @@ export function commitProfilerPostCommit( commitProfilerPostCommitImpl, finishedWork, current, - commitTime, + commitStartTime, passiveEffectDuration, ); } else { commitProfilerPostCommitImpl( finishedWork, current, - commitTime, + commitStartTime, passiveEffectDuration, ); } diff --git a/packages/react-reconciler/src/ReactFiberCommitWork.js b/packages/react-reconciler/src/ReactFiberCommitWork.js index 5965dbe8db0a8..89aa35d760b26 100644 --- a/packages/react-reconciler/src/ReactFiberCommitWork.js +++ b/packages/react-reconciler/src/ReactFiberCommitWork.js @@ -99,8 +99,7 @@ import { Cloned, } from './ReactFiberFlags'; import { - commitTime, - completeTime, + commitStartTime, pushNestedEffectDurations, popNestedEffectDurations, bubbleNestedEffectDurations, @@ -505,7 +504,7 @@ function commitLayoutEffectOnFiber( commitProfilerUpdate( finishedWork, current, - commitTime, + commitStartTime, profilerInstance.effectDuration, ); } else { @@ -2345,7 +2344,7 @@ export function reappearLayoutEffects( commitProfilerUpdate( finishedWork, current, - commitTime, + commitStartTime, profilerInstance.effectDuration, ); } else { @@ -2568,6 +2567,7 @@ export function commitPassiveMountEffects( finishedWork: Fiber, committedLanes: Lanes, committedTransitions: Array | null, + renderEndTime: number, // Profiling-only ): void { resetComponentEffectTimers(); @@ -2576,7 +2576,7 @@ export function commitPassiveMountEffects( finishedWork, committedLanes, committedTransitions, - enableProfilerTimer && enableComponentPerformanceTrack ? completeTime : 0, + enableProfilerTimer && enableComponentPerformanceTrack ? renderEndTime : 0, ); } @@ -2763,7 +2763,7 @@ function commitPassiveMountOnFiber( finishedWork.alternate, // This value will still reflect the previous commit phase. // It does not get reset until the start of the next commit phase. - commitTime, + commitStartTime, profilerInstance.passiveEffectDuration, ); } else { diff --git a/packages/react-reconciler/src/ReactFiberPerformanceTrack.js b/packages/react-reconciler/src/ReactFiberPerformanceTrack.js index 94a7ec458fc57..3d52dcf4e1073 100644 --- a/packages/react-reconciler/src/ReactFiberPerformanceTrack.js +++ b/packages/react-reconciler/src/ReactFiberPerformanceTrack.js @@ -164,3 +164,68 @@ export function logTransitionStart( } } } + +export function logRenderPhase(startTime: number, endTime: number): void { + if (supportsUserTiming) { + reusableComponentDevToolDetails.color = 'primary-dark'; + reusableComponentOptions.start = startTime; + reusableComponentOptions.end = endTime; + performance.measure('Render', reusableComponentOptions); + } +} + +export function logSuspenseThrottlePhase( + startTime: number, + endTime: number, +): void { + // This was inside a throttled Suspense boundary commit. + if (supportsUserTiming) { + reusableComponentDevToolDetails.color = 'secondary-light'; + reusableComponentOptions.start = startTime; + reusableComponentOptions.end = endTime; + performance.measure('Throttled', reusableComponentOptions); + } +} + +export function logSuspendedCommitPhase( + startTime: number, + endTime: number, +): void { + // This means the commit was suspended on CSS or images. + if (supportsUserTiming) { + reusableComponentDevToolDetails.color = 'secondary-light'; + reusableComponentOptions.start = startTime; + reusableComponentOptions.end = endTime; + performance.measure('Suspended', reusableComponentOptions); + } +} + +export function logCommitPhase(startTime: number, endTime: number): void { + if (supportsUserTiming) { + reusableComponentDevToolDetails.color = 'secondary-dark'; + reusableComponentOptions.start = startTime; + reusableComponentOptions.end = endTime; + performance.measure('Commit', reusableComponentOptions); + } +} + +export function logPaintYieldPhase(startTime: number, endTime: number): void { + if (supportsUserTiming) { + reusableComponentDevToolDetails.color = 'secondary-light'; + reusableComponentOptions.start = startTime; + reusableComponentOptions.end = endTime; + performance.measure('Waiting for Paint', reusableComponentOptions); + } +} + +export function logPassiveCommitPhase( + startTime: number, + endTime: number, +): void { + if (supportsUserTiming) { + reusableComponentDevToolDetails.color = 'secondary-dark'; + reusableComponentOptions.start = startTime; + reusableComponentOptions.end = endTime; + performance.measure('Remaining Effects', reusableComponentOptions); + } +} diff --git a/packages/react-reconciler/src/ReactFiberWorkLoop.js b/packages/react-reconciler/src/ReactFiberWorkLoop.js index b576309dc84ab..c13b9c65a65a4 100644 --- a/packages/react-reconciler/src/ReactFiberWorkLoop.js +++ b/packages/react-reconciler/src/ReactFiberWorkLoop.js @@ -71,6 +71,12 @@ import { import { logBlockingStart, logTransitionStart, + logRenderPhase, + logSuspenseThrottlePhase, + logSuspendedCommitPhase, + logCommitPhase, + logPaintYieldPhase, + logPassiveCommitPhase, } from './ReactFiberPerformanceTrack'; import { @@ -239,9 +245,11 @@ import { clampTransitionTimers, markNestedUpdateScheduled, renderStartTime, + commitStartTime, + commitEndTime, recordRenderTime, - recordCompleteTime, recordCommitTime, + recordCommitEndTime, resetNestedUpdateFlag, startProfilerTimer, stopProfilerTimerIfRunningAndRecordDuration, @@ -601,6 +609,7 @@ let rootDoesHavePassiveEffects: boolean = false; let rootWithPendingPassiveEffects: FiberRoot | null = null; let pendingPassiveEffectsLanes: Lanes = NoLanes; let pendingPassiveEffectsRemainingLanes: Lanes = NoLanes; +let pendingPassiveEffectsRenderEndTime: number = -0; // Profiling-only let pendingPassiveTransitions: Array | null = null; // Use these to prevent an infinite loop of nested updates @@ -1119,10 +1128,11 @@ function finishConcurrentRender( finishedWork: Fiber, lanes: Lanes, ) { + let renderEndTime = 0; if (enableProfilerTimer && enableComponentPerformanceTrack) { // Track when we finished the last unit of work, before we actually commit it. // The commit can be suspended/blocked until we commit it. - recordCompleteTime(); + renderEndTime = now(); } // TODO: The fact that most of these branches are identical suggests that some @@ -1182,6 +1192,9 @@ function finishConcurrentRender( workInProgressDeferredLane, workInProgressRootInterleavedUpdatedLanes, workInProgressSuspendedRetryLanes, + IMMEDIATE_COMMIT, + renderStartTime, + renderEndTime, ); } else { if ( @@ -1227,6 +1240,9 @@ function finishConcurrentRender( workInProgressRootInterleavedUpdatedLanes, workInProgressSuspendedRetryLanes, workInProgressRootDidSkipSuspendedSiblings, + THROTTLED_COMMIT, + renderStartTime, + renderEndTime, ), msUntilTimeout, ); @@ -1244,6 +1260,9 @@ function finishConcurrentRender( workInProgressRootInterleavedUpdatedLanes, workInProgressSuspendedRetryLanes, workInProgressRootDidSkipSuspendedSiblings, + IMMEDIATE_COMMIT, + renderStartTime, + renderEndTime, ); } } @@ -1259,6 +1278,9 @@ function commitRootWhenReady( updatedLanes: Lanes, suspendedRetryLanes: Lanes, didSkipSuspendedSiblings: boolean, + suspendedCommitReason: SuspendedCommitReason, // Profiling-only + completedRenderStartTime: number, // Profiling-only + completedRenderEndTime: number, // Profiling-only ) { // TODO: Combine retry throttling with Suspensey commits. Right now they run // one after the other. @@ -1299,6 +1321,7 @@ function commitRootWhenReady( spawnedLane, updatedLanes, suspendedRetryLanes, + SUSPENDED_COMMIT, ), ); markRootSuspended(root, lanes, spawnedLane, didSkipSuspendedSiblings); @@ -1315,6 +1338,9 @@ function commitRootWhenReady( spawnedLane, updatedLanes, suspendedRetryLanes, + suspendedCommitReason, + completedRenderStartTime, + completedRenderEndTime, ); } @@ -1506,8 +1532,9 @@ export function performSyncWorkOnRoot(root: FiberRoot, lanes: Lanes): null { return null; } + let renderEndTime = 0; if (enableProfilerTimer && enableComponentPerformanceTrack) { - recordCompleteTime(); + renderEndTime = now(); } // We now have a consistent tree. Because this is a sync render, we @@ -1523,6 +1550,9 @@ export function performSyncWorkOnRoot(root: FiberRoot, lanes: Lanes): null { workInProgressDeferredLane, workInProgressRootInterleavedUpdatedLanes, workInProgressSuspendedRetryLanes, + IMMEDIATE_COMMIT, + renderStartTime, + renderEndTime, ); // Before exiting, make sure there's a callback scheduled for the next @@ -3016,6 +3046,11 @@ function unwindUnitOfWork(unitOfWork: Fiber, skipSiblings: boolean): void { workInProgress = null; } +type SuspendedCommitReason = 0 | 1 | 2; +const IMMEDIATE_COMMIT = 0; +const SUSPENDED_COMMIT = 1; +const THROTTLED_COMMIT = 2; + function commitRoot( root: FiberRoot, recoverableErrors: null | Array>, @@ -3024,6 +3059,9 @@ function commitRoot( spawnedLane: Lane, updatedLanes: Lanes, suspendedRetryLanes: Lanes, + suspendedCommitReason: SuspendedCommitReason, // Profiling-only + completedRenderStartTime: number, // Profiling-only + completedRenderEndTime: number, // Profiling-only ) { // TODO: This no longer makes any sense. We already wrap the mutation and // layout phases. Should be able to remove. @@ -3041,6 +3079,9 @@ function commitRoot( spawnedLane, updatedLanes, suspendedRetryLanes, + suspendedCommitReason, + completedRenderStartTime, + completedRenderEndTime, ); } finally { ReactSharedInternals.T = prevTransition; @@ -3059,6 +3100,9 @@ function commitRootImpl( spawnedLane: Lane, updatedLanes: Lanes, suspendedRetryLanes: Lanes, + suspendedCommitReason: SuspendedCommitReason, // Profiling-only + completedRenderStartTime: number, // Profiling-only + completedRenderEndTime: number, // Profiling-only ) { do { // `flushPassiveEffects` will call `flushSyncUpdateQueue` at the end, which @@ -3078,6 +3122,12 @@ function commitRootImpl( const finishedWork = root.finishedWork; const lanes = root.finishedLanes; + if (enableProfilerTimer && enableComponentPerformanceTrack) { + // Log the previous render phase once we commit. I.e. we weren't interrupted. + setCurrentTrackFromLanes(lanes); + logRenderPhase(completedRenderStartTime, completedRenderEndTime); + } + if (__DEV__) { if (enableDebugTracing) { logCommitStarted(lanes); @@ -3174,6 +3224,7 @@ function commitRootImpl( if (!rootDoesHavePassiveEffects) { rootDoesHavePassiveEffects = true; pendingPassiveEffectsRemainingLanes = remainingLanes; + pendingPassiveEffectsRenderEndTime = completedRenderEndTime; // workInProgressTransitions might be overwritten, so we want // to store it in pendingPassiveTransitions until they get processed // We need to pass this through as an argument to commitRoot @@ -3182,7 +3233,7 @@ function commitRootImpl( // with setTimeout pendingPassiveTransitions = transitions; scheduleCallback(NormalSchedulerPriority, () => { - flushPassiveEffects(); + flushPassiveEffects(true); // 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) @@ -3191,6 +3242,19 @@ function commitRootImpl( } } + if (enableProfilerTimer) { + // Mark the current commit time to be shared by all Profilers in this + // batch. This enables them to be grouped later. + recordCommitTime(); + if (enableComponentPerformanceTrack) { + if (suspendedCommitReason === SUSPENDED_COMMIT) { + logSuspendedCommitPhase(completedRenderEndTime, commitStartTime); + } else if (suspendedCommitReason === THROTTLED_COMMIT) { + logSuspenseThrottlePhase(completedRenderEndTime, commitStartTime); + } + } + } + // Check if there are any effects in the whole tree. // TODO: This is left over from the effect list implementation, where we had // to check for the existence of `firstEffect` to satisfy Flow. I think the @@ -3226,12 +3290,6 @@ function commitRootImpl( finishedWork, ); - if (enableProfilerTimer) { - // Mark the current commit time to be shared by all Profilers in this - // batch. This enables them to be grouped later. - recordCommitTime(); - } - // The next phase is the mutation phase, where we mutate the host tree. commitMutationEffects(root, finishedWork, lanes); @@ -3282,12 +3340,11 @@ function commitRootImpl( } else { // No effects. root.current = finishedWork; - // Measure these anyway so the flamegraph explicitly shows that there were - // no effects. - // TODO: Maybe there's a better way to report this. - if (enableProfilerTimer) { - recordCommitTime(); - } + } + + if (enableProfilerTimer && enableComponentPerformanceTrack) { + recordCommitEndTime(); + logCommitPhase(commitStartTime, commitEndTime); } const rootDidHavePassiveEffects = rootDoesHavePassiveEffects; @@ -3504,7 +3561,7 @@ function releaseRootPooledCache(root: FiberRoot, remainingLanes: Lanes) { } } -export function flushPassiveEffects(): boolean { +export function flushPassiveEffects(wasDelayedCommit?: boolean): boolean { // Returns whether passive effects were flushed. // TODO: Combine this check with the one in flushPassiveEFfectsImpl. We should // probably just combine the two functions. I believe they were only separate @@ -3529,7 +3586,7 @@ export function flushPassiveEffects(): boolean { try { setCurrentUpdatePriority(priority); ReactSharedInternals.T = null; - return flushPassiveEffectsImpl(); + return flushPassiveEffectsImpl(wasDelayedCommit); } finally { setCurrentUpdatePriority(previousPriority); ReactSharedInternals.T = prevTransition; @@ -3543,7 +3600,7 @@ export function flushPassiveEffects(): boolean { return false; } -function flushPassiveEffectsImpl() { +function flushPassiveEffectsImpl(wasDelayedCommit: void | boolean) { if (rootWithPendingPassiveEffects === null) { return false; } @@ -3579,6 +3636,12 @@ function flushPassiveEffectsImpl() { } } + let passiveEffectStartTime = 0; + if (enableProfilerTimer && enableComponentPerformanceTrack) { + passiveEffectStartTime = now(); + logPaintYieldPhase(commitEndTime, passiveEffectStartTime); + } + if (enableSchedulingProfiler) { markPassiveEffectsStarted(lanes); } @@ -3587,7 +3650,13 @@ function flushPassiveEffectsImpl() { executionContext |= CommitContext; commitPassiveUnmountEffects(root.current); - commitPassiveMountEffects(root, root.current, lanes, transitions); + commitPassiveMountEffects( + root, + root.current, + lanes, + transitions, + pendingPassiveEffectsRenderEndTime, + ); if (__DEV__) { if (enableDebugTracing) { @@ -3606,7 +3675,11 @@ function flushPassiveEffectsImpl() { executionContext = prevExecutionContext; if (enableProfilerTimer && enableComponentPerformanceTrack) { - finalizeRender(lanes, now()); + const passiveEffectsEndTime = now(); + if (wasDelayedCommit) { + logPassiveCommitPhase(passiveEffectStartTime, passiveEffectsEndTime); + } + finalizeRender(lanes, passiveEffectsEndTime); } flushSyncWorkOnAllRoots(); diff --git a/packages/react-reconciler/src/ReactProfilerTimer.js b/packages/react-reconciler/src/ReactProfilerTimer.js index cf3133524813e..0df3427fe86b2 100644 --- a/packages/react-reconciler/src/ReactProfilerTimer.js +++ b/packages/react-reconciler/src/ReactProfilerTimer.js @@ -28,8 +28,8 @@ 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 commitStartTime: number = -0; +export let commitEndTime: number = -0; export let profilerStartTime: number = -1.1; export let profilerEffectDuration: number = -0; export let componentEffectDuration: number = -0; @@ -255,18 +255,18 @@ export function recordRenderTime(): void { renderStartTime = now(); } -export function recordCompleteTime(): void { +export function recordCommitTime(): void { if (!enableProfilerTimer) { return; } - completeTime = now(); + commitStartTime = now(); } -export function recordCommitTime(): void { +export function recordCommitEndTime(): void { if (!enableProfilerTimer) { return; } - commitTime = now(); + commitEndTime = now(); } export function startProfilerTimer(fiber: Fiber): void { diff --git a/packages/react/src/__tests__/ReactProfiler-test.internal.js b/packages/react/src/__tests__/ReactProfiler-test.internal.js index 14aacca63a7ca..522c3a11cf29d 100644 --- a/packages/react/src/__tests__/ReactProfiler-test.internal.js +++ b/packages/react/src/__tests__/ReactProfiler-test.internal.js @@ -181,6 +181,7 @@ describe(`onRender`, () => { 'read current time', 'read current time', 'read current time', + 'read current time', ]); } else { assertLog([ @@ -218,6 +219,7 @@ describe(`onRender`, () => { 'read current time', 'read current time', 'read current time', + 'read current time', ]); } else { assertLog([