From 8f79452dd7bc510f6eef36d68f2fbf896a7a07bc Mon Sep 17 00:00:00 2001 From: Sebastian Markbage Date: Fri, 20 Sep 2024 17:42:04 -0400 Subject: [PATCH 1/8] Rename commitTime to commitStartTime and completeTime to renderEndTime --- .../src/ReactFiberCommitEffects.js | 22 +++++++++---------- .../src/ReactFiberCommitWork.js | 12 +++++----- .../src/ReactProfilerTimer.js | 8 +++---- 3 files changed, 21 insertions(+), 21 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..6ec95be228ff5 100644 --- a/packages/react-reconciler/src/ReactFiberCommitWork.js +++ b/packages/react-reconciler/src/ReactFiberCommitWork.js @@ -99,8 +99,8 @@ import { Cloned, } from './ReactFiberFlags'; import { - commitTime, - completeTime, + commitStartTime, + renderEndTime, pushNestedEffectDurations, popNestedEffectDurations, bubbleNestedEffectDurations, @@ -505,7 +505,7 @@ function commitLayoutEffectOnFiber( commitProfilerUpdate( finishedWork, current, - commitTime, + commitStartTime, profilerInstance.effectDuration, ); } else { @@ -2345,7 +2345,7 @@ export function reappearLayoutEffects( commitProfilerUpdate( finishedWork, current, - commitTime, + commitStartTime, profilerInstance.effectDuration, ); } else { @@ -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/ReactProfilerTimer.js b/packages/react-reconciler/src/ReactProfilerTimer.js index cf3133524813e..7e20be7a0d8dc 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 renderEndTime: number = -0; +export let commitStartTime: number = -0; export let profilerStartTime: number = -1.1; export let profilerEffectDuration: number = -0; export let componentEffectDuration: number = -0; @@ -259,14 +259,14 @@ export function recordCompleteTime(): void { if (!enableProfilerTimer) { return; } - completeTime = now(); + renderEndTime = now(); } export function recordCommitTime(): void { if (!enableProfilerTimer) { return; } - commitTime = now(); + commitStartTime = now(); } export function startProfilerTimer(fiber: Fiber): void { From 5e797dcc8d424aba5e20dc6520aa5360c4dc9145 Mon Sep 17 00:00:00 2001 From: Sebastian Markbage Date: Fri, 20 Sep 2024 18:18:44 -0400 Subject: [PATCH 2/8] Move commit time before to before mutation effects This affects the Profiler component as well but really this metric should indicate when we started the commit and if something else was blocking it before. Usually there's nothing in before mutation effects. --- packages/react-reconciler/src/ReactFiberWorkLoop.js | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/packages/react-reconciler/src/ReactFiberWorkLoop.js b/packages/react-reconciler/src/ReactFiberWorkLoop.js index b576309dc84ab..c1413e72e34a4 100644 --- a/packages/react-reconciler/src/ReactFiberWorkLoop.js +++ b/packages/react-reconciler/src/ReactFiberWorkLoop.js @@ -3218,6 +3218,12 @@ function commitRootImpl( // of the effect list for each phase: all mutation effects come before all // layout effects, and so on. + 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 first phase a "before mutation" phase. We use this phase to read the // state of the host tree right before we mutate it. This is where // getSnapshotBeforeUpdate is called. @@ -3226,12 +3232,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); From 33c963434ad0ea7e661387b3c68f95125886ade3 Mon Sep 17 00:00:00 2001 From: Sebastian Markbage Date: Fri, 20 Sep 2024 19:33:53 -0400 Subject: [PATCH 3/8] Track commit end time --- packages/react-reconciler/src/ReactFiberWorkLoop.js | 8 ++++++++ packages/react-reconciler/src/ReactProfilerTimer.js | 8 ++++++++ 2 files changed, 16 insertions(+) diff --git a/packages/react-reconciler/src/ReactFiberWorkLoop.js b/packages/react-reconciler/src/ReactFiberWorkLoop.js index c1413e72e34a4..802413d270919 100644 --- a/packages/react-reconciler/src/ReactFiberWorkLoop.js +++ b/packages/react-reconciler/src/ReactFiberWorkLoop.js @@ -242,6 +242,7 @@ import { recordRenderTime, recordCompleteTime, recordCommitTime, + recordCommitEndTime, resetNestedUpdateFlag, startProfilerTimer, stopProfilerTimerIfRunningAndRecordDuration, @@ -3270,6 +3271,10 @@ function commitRootImpl( markLayoutEffectsStopped(); } + if (enableProfilerTimer && enableComponentPerformanceTrack) { + recordCommitEndTime(); + } + // Tell Scheduler to yield at the end of the frame, so the browser has an // opportunity to paint. requestPaint(); @@ -3287,6 +3292,9 @@ function commitRootImpl( // TODO: Maybe there's a better way to report this. if (enableProfilerTimer) { recordCommitTime(); + if (enableComponentPerformanceTrack) { + recordCommitEndTime(); + } } } diff --git a/packages/react-reconciler/src/ReactProfilerTimer.js b/packages/react-reconciler/src/ReactProfilerTimer.js index 7e20be7a0d8dc..96eaa0a08192c 100644 --- a/packages/react-reconciler/src/ReactProfilerTimer.js +++ b/packages/react-reconciler/src/ReactProfilerTimer.js @@ -30,6 +30,7 @@ const {unstable_now: now} = Scheduler; export let renderStartTime: number = -0; export let renderEndTime: 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; @@ -269,6 +270,13 @@ export function recordCommitTime(): void { commitStartTime = now(); } +export function recordCommitEndTime(): void { + if (!enableProfilerTimer) { + return; + } + commitEndTime = now(); +} + export function startProfilerTimer(fiber: Fiber): void { if (!enableProfilerTimer) { return; From 177c67b0910dcb72f1e85df509e4c10f1f46dfce Mon Sep 17 00:00:00 2001 From: Sebastian Markbage Date: Fri, 20 Sep 2024 19:38:27 -0400 Subject: [PATCH 4/8] Log the render phase when it completes --- .../react-reconciler/src/ReactFiberPerformanceTrack.js | 9 +++++++++ packages/react-reconciler/src/ReactFiberWorkLoop.js | 6 ++++++ 2 files changed, 15 insertions(+) diff --git a/packages/react-reconciler/src/ReactFiberPerformanceTrack.js b/packages/react-reconciler/src/ReactFiberPerformanceTrack.js index 94a7ec458fc57..5b821995f7607 100644 --- a/packages/react-reconciler/src/ReactFiberPerformanceTrack.js +++ b/packages/react-reconciler/src/ReactFiberPerformanceTrack.js @@ -164,3 +164,12 @@ export function logTransitionStart( } } } + +export function logRenderPhase(startTime: number, endTime: number): void { + if (supportsUserTiming) { + reusableComponentDevToolDetails.color = 'primary-light'; + reusableComponentOptions.start = startTime; + reusableComponentOptions.end = endTime; + performance.measure('Render', reusableComponentOptions); + } +} diff --git a/packages/react-reconciler/src/ReactFiberWorkLoop.js b/packages/react-reconciler/src/ReactFiberWorkLoop.js index 802413d270919..a9bd1bbcad550 100644 --- a/packages/react-reconciler/src/ReactFiberWorkLoop.js +++ b/packages/react-reconciler/src/ReactFiberWorkLoop.js @@ -71,6 +71,7 @@ import { import { logBlockingStart, logTransitionStart, + logRenderPhase, } from './ReactFiberPerformanceTrack'; import { @@ -239,6 +240,7 @@ import { clampTransitionTimers, markNestedUpdateScheduled, renderStartTime, + renderEndTime, recordRenderTime, recordCompleteTime, recordCommitTime, @@ -1124,6 +1126,8 @@ function finishConcurrentRender( // 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(); + setCurrentTrackFromLanes(lanes); + logRenderPhase(renderStartTime, renderEndTime); } // TODO: The fact that most of these branches are identical suggests that some @@ -1509,6 +1513,8 @@ export function performSyncWorkOnRoot(root: FiberRoot, lanes: Lanes): null { if (enableProfilerTimer && enableComponentPerformanceTrack) { recordCompleteTime(); + setCurrentTrackFromLanes(lanes); + logRenderPhase(renderStartTime, renderEndTime); } // We now have a consistent tree. Because this is a sync render, we From ee285e3aebe6c22c80cd8864571c38e6dbef9d6a Mon Sep 17 00:00:00 2001 From: Sebastian Markbage Date: Fri, 20 Sep 2024 19:49:46 -0400 Subject: [PATCH 5/8] Log commit phases and the gap between the render/commit and commit/passive If the commit phase is delayed due to throttling we log the phase in between as "Throttled". If it's delayed due to CSS/image suspending then we log it as "Suspended". If the passive phase is delayed until the scheduled task we log it as "Waiting for Paint". If the passive phase is immediate or forced due to another update, we don't log anything about the gap. --- .../src/ReactFiberPerformanceTrack.js | 58 +++++++++++++- .../src/ReactFiberWorkLoop.js | 79 +++++++++++++------ 2 files changed, 112 insertions(+), 25 deletions(-) diff --git a/packages/react-reconciler/src/ReactFiberPerformanceTrack.js b/packages/react-reconciler/src/ReactFiberPerformanceTrack.js index 5b821995f7607..3d52dcf4e1073 100644 --- a/packages/react-reconciler/src/ReactFiberPerformanceTrack.js +++ b/packages/react-reconciler/src/ReactFiberPerformanceTrack.js @@ -167,9 +167,65 @@ export function logTransitionStart( export function logRenderPhase(startTime: number, endTime: number): void { if (supportsUserTiming) { - reusableComponentDevToolDetails.color = 'primary-light'; + 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 a9bd1bbcad550..89c3731b3aee6 100644 --- a/packages/react-reconciler/src/ReactFiberWorkLoop.js +++ b/packages/react-reconciler/src/ReactFiberWorkLoop.js @@ -72,6 +72,11 @@ import { logBlockingStart, logTransitionStart, logRenderPhase, + logSuspenseThrottlePhase, + logSuspendedCommitPhase, + logCommitPhase, + logPaintYieldPhase, + logPassiveCommitPhase, } from './ReactFiberPerformanceTrack'; import { @@ -241,6 +246,8 @@ import { markNestedUpdateScheduled, renderStartTime, renderEndTime, + commitStartTime, + commitEndTime, recordRenderTime, recordCompleteTime, recordCommitTime, @@ -1187,6 +1194,7 @@ function finishConcurrentRender( workInProgressDeferredLane, workInProgressRootInterleavedUpdatedLanes, workInProgressSuspendedRetryLanes, + IMMEDIATE_COMMIT, ); } else { if ( @@ -1232,6 +1240,7 @@ function finishConcurrentRender( workInProgressRootInterleavedUpdatedLanes, workInProgressSuspendedRetryLanes, workInProgressRootDidSkipSuspendedSiblings, + THROTTLED_COMMIT, ), msUntilTimeout, ); @@ -1249,6 +1258,7 @@ function finishConcurrentRender( workInProgressRootInterleavedUpdatedLanes, workInProgressSuspendedRetryLanes, workInProgressRootDidSkipSuspendedSiblings, + IMMEDIATE_COMMIT, ); } } @@ -1264,6 +1274,7 @@ function commitRootWhenReady( updatedLanes: Lanes, suspendedRetryLanes: Lanes, didSkipSuspendedSiblings: boolean, + suspendedCommitReason: SuspendedCommitReason, ) { // TODO: Combine retry throttling with Suspensey commits. Right now they run // one after the other. @@ -1304,6 +1315,7 @@ function commitRootWhenReady( spawnedLane, updatedLanes, suspendedRetryLanes, + SUSPENDED_COMMIT, ), ); markRootSuspended(root, lanes, spawnedLane, didSkipSuspendedSiblings); @@ -1320,6 +1332,7 @@ function commitRootWhenReady( spawnedLane, updatedLanes, suspendedRetryLanes, + suspendedCommitReason, ); } @@ -1530,6 +1543,7 @@ export function performSyncWorkOnRoot(root: FiberRoot, lanes: Lanes): null { workInProgressDeferredLane, workInProgressRootInterleavedUpdatedLanes, workInProgressSuspendedRetryLanes, + IMMEDIATE_COMMIT, ); // Before exiting, make sure there's a callback scheduled for the next @@ -3023,6 +3037,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>, @@ -3031,6 +3050,7 @@ function commitRoot( spawnedLane: Lane, updatedLanes: Lanes, suspendedRetryLanes: Lanes, + suspendedCommitReason: SuspendedCommitReason, ) { // TODO: This no longer makes any sense. We already wrap the mutation and // layout phases. Should be able to remove. @@ -3048,6 +3068,7 @@ function commitRoot( spawnedLane, updatedLanes, suspendedRetryLanes, + suspendedCommitReason, ); } finally { ReactSharedInternals.T = prevTransition; @@ -3066,6 +3087,7 @@ function commitRootImpl( spawnedLane: Lane, updatedLanes: Lanes, suspendedRetryLanes: Lanes, + suspendedCommitReason: SuspendedCommitReason, ) { do { // `flushPassiveEffects` will call `flushSyncUpdateQueue` at the end, which @@ -3189,7 +3211,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) @@ -3198,6 +3220,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(renderEndTime, commitStartTime); + } else if (suspendedCommitReason === THROTTLED_COMMIT) { + logSuspenseThrottlePhase(renderEndTime, 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 @@ -3225,12 +3260,6 @@ function commitRootImpl( // of the effect list for each phase: all mutation effects come before all // layout effects, and so on. - 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 first phase a "before mutation" phase. We use this phase to read the // state of the host tree right before we mutate it. This is where // getSnapshotBeforeUpdate is called. @@ -3277,10 +3306,6 @@ function commitRootImpl( markLayoutEffectsStopped(); } - if (enableProfilerTimer && enableComponentPerformanceTrack) { - recordCommitEndTime(); - } - // Tell Scheduler to yield at the end of the frame, so the browser has an // opportunity to paint. requestPaint(); @@ -3293,15 +3318,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 (enableComponentPerformanceTrack) { - recordCommitEndTime(); - } - } + } + + if (enableProfilerTimer && enableComponentPerformanceTrack) { + recordCommitEndTime(); + logCommitPhase(commitStartTime, commitEndTime); } const rootDidHavePassiveEffects = rootDoesHavePassiveEffects; @@ -3518,7 +3539,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 @@ -3543,7 +3564,7 @@ export function flushPassiveEffects(): boolean { try { setCurrentUpdatePriority(priority); ReactSharedInternals.T = null; - return flushPassiveEffectsImpl(); + return flushPassiveEffectsImpl(wasDelayedCommit); } finally { setCurrentUpdatePriority(previousPriority); ReactSharedInternals.T = prevTransition; @@ -3557,7 +3578,7 @@ export function flushPassiveEffects(): boolean { return false; } -function flushPassiveEffectsImpl() { +function flushPassiveEffectsImpl(wasDelayedCommit: void | boolean) { if (rootWithPendingPassiveEffects === null) { return false; } @@ -3593,6 +3614,12 @@ function flushPassiveEffectsImpl() { } } + let passiveEffectStartTime = 0; + if (enableProfilerTimer && enableComponentPerformanceTrack) { + passiveEffectStartTime = now(); + logPaintYieldPhase(commitEndTime, passiveEffectStartTime); + } + if (enableSchedulingProfiler) { markPassiveEffectsStarted(lanes); } @@ -3620,7 +3647,11 @@ function flushPassiveEffectsImpl() { executionContext = prevExecutionContext; if (enableProfilerTimer && enableComponentPerformanceTrack) { - finalizeRender(lanes, now()); + const passiveEffectsEndTime = now(); + if (wasDelayedCommit) { + logPassiveCommitPhase(passiveEffectStartTime, passiveEffectsEndTime); + } + finalizeRender(lanes, passiveEffectsEndTime); } flushSyncWorkOnAllRoots(); From c540e55d322f00b4ca52d4fda9f7f6daabca9c97 Mon Sep 17 00:00:00 2001 From: Sebastian Markbage Date: Fri, 20 Sep 2024 21:20:59 -0400 Subject: [PATCH 6/8] Update tests --- packages/react/src/__tests__/ReactProfiler-test.internal.js | 2 ++ 1 file changed, 2 insertions(+) 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([ From 214697b6edf22993a7f085d8706ba110e4adf52c Mon Sep 17 00:00:00 2001 From: Sebastian Markbage Date: Mon, 23 Sep 2024 10:47:01 -0700 Subject: [PATCH 7/8] Move renderStartTime and renderEndTime to the commit closure Since multiple roots can start rendering and overriding these while the commit is still pending. Then we need to stash it temporarily on module scope for the passive effect. Same as lanes. --- .../src/ReactFiberCommitWork.js | 2 +- .../src/ReactFiberWorkLoop.js | 46 +++++++++++++++---- .../src/ReactProfilerTimer.js | 8 ---- 3 files changed, 37 insertions(+), 19 deletions(-) diff --git a/packages/react-reconciler/src/ReactFiberCommitWork.js b/packages/react-reconciler/src/ReactFiberCommitWork.js index 6ec95be228ff5..89aa35d760b26 100644 --- a/packages/react-reconciler/src/ReactFiberCommitWork.js +++ b/packages/react-reconciler/src/ReactFiberCommitWork.js @@ -100,7 +100,6 @@ import { } from './ReactFiberFlags'; import { commitStartTime, - renderEndTime, pushNestedEffectDurations, popNestedEffectDurations, bubbleNestedEffectDurations, @@ -2568,6 +2567,7 @@ export function commitPassiveMountEffects( finishedWork: Fiber, committedLanes: Lanes, committedTransitions: Array | null, + renderEndTime: number, // Profiling-only ): void { resetComponentEffectTimers(); diff --git a/packages/react-reconciler/src/ReactFiberWorkLoop.js b/packages/react-reconciler/src/ReactFiberWorkLoop.js index 89c3731b3aee6..b7e35afb56e96 100644 --- a/packages/react-reconciler/src/ReactFiberWorkLoop.js +++ b/packages/react-reconciler/src/ReactFiberWorkLoop.js @@ -245,11 +245,9 @@ import { clampTransitionTimers, markNestedUpdateScheduled, renderStartTime, - renderEndTime, commitStartTime, commitEndTime, recordRenderTime, - recordCompleteTime, recordCommitTime, recordCommitEndTime, resetNestedUpdateFlag, @@ -611,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 @@ -1129,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(); setCurrentTrackFromLanes(lanes); logRenderPhase(renderStartTime, renderEndTime); } @@ -1195,6 +1195,8 @@ function finishConcurrentRender( workInProgressRootInterleavedUpdatedLanes, workInProgressSuspendedRetryLanes, IMMEDIATE_COMMIT, + renderStartTime, + renderEndTime, ); } else { if ( @@ -1241,6 +1243,8 @@ function finishConcurrentRender( workInProgressSuspendedRetryLanes, workInProgressRootDidSkipSuspendedSiblings, THROTTLED_COMMIT, + renderStartTime, + renderEndTime, ), msUntilTimeout, ); @@ -1259,6 +1263,8 @@ function finishConcurrentRender( workInProgressSuspendedRetryLanes, workInProgressRootDidSkipSuspendedSiblings, IMMEDIATE_COMMIT, + renderStartTime, + renderEndTime, ); } } @@ -1274,7 +1280,9 @@ function commitRootWhenReady( updatedLanes: Lanes, suspendedRetryLanes: Lanes, didSkipSuspendedSiblings: boolean, - suspendedCommitReason: SuspendedCommitReason, + 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. @@ -1333,6 +1341,8 @@ function commitRootWhenReady( updatedLanes, suspendedRetryLanes, suspendedCommitReason, + completedRenderStartTime, + completedRenderEndTime, ); } @@ -1524,8 +1534,9 @@ export function performSyncWorkOnRoot(root: FiberRoot, lanes: Lanes): null { return null; } + let renderEndTime = 0; if (enableProfilerTimer && enableComponentPerformanceTrack) { - recordCompleteTime(); + renderEndTime = now(); setCurrentTrackFromLanes(lanes); logRenderPhase(renderStartTime, renderEndTime); } @@ -1544,6 +1555,8 @@ export function performSyncWorkOnRoot(root: FiberRoot, lanes: Lanes): null { workInProgressRootInterleavedUpdatedLanes, workInProgressSuspendedRetryLanes, IMMEDIATE_COMMIT, + renderStartTime, + renderEndTime, ); // Before exiting, make sure there's a callback scheduled for the next @@ -3050,7 +3063,9 @@ function commitRoot( spawnedLane: Lane, updatedLanes: Lanes, suspendedRetryLanes: Lanes, - suspendedCommitReason: SuspendedCommitReason, + 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. @@ -3069,6 +3084,8 @@ function commitRoot( updatedLanes, suspendedRetryLanes, suspendedCommitReason, + completedRenderStartTime, + completedRenderEndTime, ); } finally { ReactSharedInternals.T = prevTransition; @@ -3087,7 +3104,9 @@ function commitRootImpl( spawnedLane: Lane, updatedLanes: Lanes, suspendedRetryLanes: Lanes, - suspendedCommitReason: SuspendedCommitReason, + suspendedCommitReason: SuspendedCommitReason, // Profiling-only + completedRenderStartTime: number, // Profiling-only + completedRenderEndTime: number, // Profiling-only ) { do { // `flushPassiveEffects` will call `flushSyncUpdateQueue` at the end, which @@ -3203,6 +3222,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 @@ -3226,9 +3246,9 @@ function commitRootImpl( recordCommitTime(); if (enableComponentPerformanceTrack) { if (suspendedCommitReason === SUSPENDED_COMMIT) { - logSuspendedCommitPhase(renderEndTime, commitStartTime); + logSuspendedCommitPhase(completedRenderEndTime, commitStartTime); } else if (suspendedCommitReason === THROTTLED_COMMIT) { - logSuspenseThrottlePhase(renderEndTime, commitStartTime); + logSuspenseThrottlePhase(completedRenderEndTime, commitStartTime); } } } @@ -3628,7 +3648,13 @@ function flushPassiveEffectsImpl(wasDelayedCommit: void | boolean) { executionContext |= CommitContext; commitPassiveUnmountEffects(root.current); - commitPassiveMountEffects(root, root.current, lanes, transitions); + commitPassiveMountEffects( + root, + root.current, + lanes, + transitions, + pendingPassiveEffectsRenderEndTime, + ); if (__DEV__) { if (enableDebugTracing) { diff --git a/packages/react-reconciler/src/ReactProfilerTimer.js b/packages/react-reconciler/src/ReactProfilerTimer.js index 96eaa0a08192c..0df3427fe86b2 100644 --- a/packages/react-reconciler/src/ReactProfilerTimer.js +++ b/packages/react-reconciler/src/ReactProfilerTimer.js @@ -28,7 +28,6 @@ import * as Scheduler from 'scheduler'; const {unstable_now: now} = Scheduler; export let renderStartTime: number = -0; -export let renderEndTime: number = -0; export let commitStartTime: number = -0; export let commitEndTime: number = -0; export let profilerStartTime: number = -1.1; @@ -256,13 +255,6 @@ export function recordRenderTime(): void { renderStartTime = now(); } -export function recordCompleteTime(): void { - if (!enableProfilerTimer) { - return; - } - renderEndTime = now(); -} - export function recordCommitTime(): void { if (!enableProfilerTimer) { return; From 3b9f88db5c7d180998fefdc5b9c3a721579c99e3 Mon Sep 17 00:00:00 2001 From: Sebastian Markbage Date: Mon, 23 Sep 2024 10:49:27 -0700 Subject: [PATCH 8/8] Log the render phase at commit time This lets us log this phase differently if it is interrupted before commit. --- packages/react-reconciler/src/ReactFiberWorkLoop.js | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/packages/react-reconciler/src/ReactFiberWorkLoop.js b/packages/react-reconciler/src/ReactFiberWorkLoop.js index b7e35afb56e96..c13b9c65a65a4 100644 --- a/packages/react-reconciler/src/ReactFiberWorkLoop.js +++ b/packages/react-reconciler/src/ReactFiberWorkLoop.js @@ -1133,8 +1133,6 @@ function finishConcurrentRender( // Track when we finished the last unit of work, before we actually commit it. // The commit can be suspended/blocked until we commit it. renderEndTime = now(); - setCurrentTrackFromLanes(lanes); - logRenderPhase(renderStartTime, renderEndTime); } // TODO: The fact that most of these branches are identical suggests that some @@ -1537,8 +1535,6 @@ export function performSyncWorkOnRoot(root: FiberRoot, lanes: Lanes): null { let renderEndTime = 0; if (enableProfilerTimer && enableComponentPerformanceTrack) { renderEndTime = now(); - setCurrentTrackFromLanes(lanes); - logRenderPhase(renderStartTime, renderEndTime); } // We now have a consistent tree. Because this is a sync render, we @@ -3126,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);