From 6177b18c66c010d2b2f03202623a0533e7a89004 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Sebastian=20Markb=C3=A5ge?= Date: Tue, 19 Nov 2024 13:42:44 -0500 Subject: [PATCH] Track suspended time when the render doesn't commit because it suspended (#31552) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit When we suspend the render with delay, we won't do any more work until we get some kind of another update/ping. It's because conceptually something is suspended and then will update later. We need to highlight this period to show why it's not doing any work. We fill the empty space with "Suspended". This stops whenever the same lane group starts rendering again. Clamped by the preceeding start time/event time/update time. Screenshot 2024-11-15 at 1 01 29 PM Ideally we would instead start the next render and suspend the work loop at all places we suspend. In that mode this will instead show up as a very long "Render" with a "Suspended" period instead highlighted in the Components track as one component is suspended. We'll soon have that for `use()` but not all updates so this covers the rest. One issue with `useActionState` is that it is implemented as suspending at the point of the `useActionState` which means that the period of the Action shows up as a suspended render instead of as an Action which happens for raw actions. This is not really how you conceptually think about it so we need some special case for `useActionState`. In the screenshot above, the first "Suspended" is actually awaiting an Action and the second "Suspended" is awaiting the data from it. --- .../src/ReactFiberPerformanceTrack.js | 13 +++ .../src/ReactFiberWorkLoop.js | 80 ++++++++++++++----- .../src/ReactProfilerTimer.js | 15 ++++ 3 files changed, 90 insertions(+), 18 deletions(-) diff --git a/packages/react-reconciler/src/ReactFiberPerformanceTrack.js b/packages/react-reconciler/src/ReactFiberPerformanceTrack.js index f43d296a8ad61..7d074d545664a 100644 --- a/packages/react-reconciler/src/ReactFiberPerformanceTrack.js +++ b/packages/react-reconciler/src/ReactFiberPerformanceTrack.js @@ -222,6 +222,19 @@ export function logSuspendedRenderPhase( } } +export function logSuspendedWithDelayPhase( + startTime: number, + endTime: number, +): void { + // This means the render was suspended and cannot commit until it gets unblocked. + if (supportsUserTiming) { + reusableLaneDevToolDetails.color = 'primary-dark'; + reusableLaneOptions.start = startTime; + reusableLaneOptions.end = endTime; + performance.measure('Suspended', reusableLaneOptions); + } +} + export function logErroredRenderPhase( startTime: number, endTime: number, diff --git a/packages/react-reconciler/src/ReactFiberWorkLoop.js b/packages/react-reconciler/src/ReactFiberWorkLoop.js index d6f2c48f8ce11..1d4f136b64510 100644 --- a/packages/react-reconciler/src/ReactFiberWorkLoop.js +++ b/packages/react-reconciler/src/ReactFiberWorkLoop.js @@ -73,6 +73,7 @@ import { logSuspendedRenderPhase, logErroredRenderPhase, logInconsistentRender, + logSuspendedWithDelayPhase, logSuspenseThrottlePhase, logSuspendedCommitPhase, logCommitPhase, @@ -239,12 +240,14 @@ import { blockingEventTime, blockingEventType, blockingEventIsRepeat, + blockingSuspendedTime, transitionClampTime, transitionStartTime, transitionUpdateTime, transitionEventTime, transitionEventType, transitionEventIsRepeat, + transitionSuspendedTime, clearBlockingTimers, clearTransitionTimers, clampBlockingTimers, @@ -260,6 +263,7 @@ import { stopProfilerTimerIfRunningAndRecordDuration, stopProfilerTimerIfRunningAndRecordIncompleteDuration, markUpdateAsRepeat, + trackSuspendedTime, } from './ReactProfilerTimer'; import {setCurrentTrackFromLanes} from './ReactFiberPerformanceTrack'; @@ -954,6 +958,11 @@ export function performWorkOnRoot( } break; } else { + let renderEndTime = 0; + if (enableProfilerTimer && enableComponentPerformanceTrack) { + renderEndTime = now(); + } + // The render completed. // Check if this render may have yielded to a concurrent event, and if so, @@ -968,7 +977,6 @@ export function performWorkOnRoot( ) { if (enableProfilerTimer && enableComponentPerformanceTrack) { setCurrentTrackFromLanes(lanes); - const renderEndTime = now(); logInconsistentRender(renderStartTime, renderEndTime); finalizeRender(lanes, renderEndTime); markUpdateAsRepeat(lanes); @@ -996,7 +1004,6 @@ export function performWorkOnRoot( if (errorRetryLanes !== NoLanes) { if (enableProfilerTimer && enableComponentPerformanceTrack) { setCurrentTrackFromLanes(lanes); - const renderEndTime = now(); logErroredRenderPhase(renderStartTime, renderEndTime); finalizeRender(lanes, renderEndTime); markUpdateAsRepeat(lanes); @@ -1020,13 +1027,15 @@ export function performWorkOnRoot( continue; } else { // The root errored yet again. Proceed to commit the tree. + if (enableProfilerTimer && enableComponentPerformanceTrack) { + renderEndTime = now(); + } } } } if (exitStatus === RootFatalErrored) { if (enableProfilerTimer && enableComponentPerformanceTrack) { setCurrentTrackFromLanes(lanes); - const renderEndTime = now(); logErroredRenderPhase(renderStartTime, renderEndTime); finalizeRender(lanes, renderEndTime); } @@ -1040,7 +1049,13 @@ export function performWorkOnRoot( // We now have a consistent tree. The next step is either to commit it, // or, if something suspended, wait to commit it after a timeout. - finishConcurrentRender(root, exitStatus, finishedWork, lanes); + finishConcurrentRender( + root, + exitStatus, + finishedWork, + lanes, + renderEndTime, + ); } break; } while (true); @@ -1139,14 +1154,8 @@ function finishConcurrentRender( exitStatus: RootExitStatus, finishedWork: Fiber, lanes: Lanes, + renderEndTime: number, // Profiling-only ) { - 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. - renderEndTime = now(); - } - // TODO: The fact that most of these branches are identical suggests that some // of the exit statuses are not best modeled as exit statuses and should be // tracked orthogonally. @@ -1170,6 +1179,7 @@ function finishConcurrentRender( setCurrentTrackFromLanes(lanes); logSuspendedRenderPhase(renderStartTime, renderEndTime); finalizeRender(lanes, renderEndTime); + trackSuspendedTime(lanes, renderEndTime); } const didAttemptEntireTree = !workInProgressRootDidSkipSuspendedSiblings; markRootSuspended( @@ -1705,13 +1715,29 @@ function prepareFreshStack(root: FiberRoot, lanes: Lanes): Fiber { } if (includesSyncLane(lanes) || includesBlockingLane(lanes)) { - logBlockingStart( + const clampedUpdateTime = blockingUpdateTime >= 0 && blockingUpdateTime < blockingClampTime ? blockingClampTime - : blockingUpdateTime, + : blockingUpdateTime; + const clampedEventTime = blockingEventTime >= 0 && blockingEventTime < blockingClampTime ? blockingClampTime - : blockingEventTime, + : blockingEventTime; + if (blockingSuspendedTime >= 0) { + setCurrentTrackFromLanes(lanes); + logSuspendedWithDelayPhase( + blockingSuspendedTime, + // Clamp the suspended time to the first event/update. + clampedEventTime >= 0 + ? clampedEventTime + : clampedUpdateTime >= 0 + ? clampedUpdateTime + : renderStartTime, + ); + } + logBlockingStart( + clampedUpdateTime, + clampedEventTime, blockingEventType, blockingEventIsRepeat, renderStartTime, @@ -1719,16 +1745,34 @@ function prepareFreshStack(root: FiberRoot, lanes: Lanes): Fiber { clearBlockingTimers(); } if (includesTransitionLane(lanes)) { - logTransitionStart( + const clampedStartTime = transitionStartTime >= 0 && transitionStartTime < transitionClampTime ? transitionClampTime - : transitionStartTime, + : transitionStartTime; + const clampedUpdateTime = transitionUpdateTime >= 0 && transitionUpdateTime < transitionClampTime ? transitionClampTime - : transitionUpdateTime, + : transitionUpdateTime; + const clampedEventTime = transitionEventTime >= 0 && transitionEventTime < transitionClampTime ? transitionClampTime - : transitionEventTime, + : transitionEventTime; + if (transitionSuspendedTime >= 0) { + setCurrentTrackFromLanes(lanes); + logSuspendedWithDelayPhase( + transitionSuspendedTime, + // Clamp the suspended time to the first event/update. + clampedEventTime >= 0 + ? clampedEventTime + : clampedUpdateTime >= 0 + ? clampedUpdateTime + : renderStartTime, + ); + } + logTransitionStart( + clampedStartTime, + clampedUpdateTime, + clampedEventTime, transitionEventType, transitionEventIsRepeat, renderStartTime, diff --git a/packages/react-reconciler/src/ReactProfilerTimer.js b/packages/react-reconciler/src/ReactProfilerTimer.js index 87d7c0324bcb5..da4e1f7bf356b 100644 --- a/packages/react-reconciler/src/ReactProfilerTimer.js +++ b/packages/react-reconciler/src/ReactProfilerTimer.js @@ -48,6 +48,7 @@ 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. export let blockingEventIsRepeat: boolean = false; +export let blockingSuspendedTime: number = -1.1; // TODO: This should really be one per Transition lane. export let transitionClampTime: number = -0; export let transitionStartTime: number = -1.1; // First startTransition call before setState. @@ -55,6 +56,7 @@ export let transitionUpdateTime: number = -1.1; // First transition setState sch export let transitionEventTime: number = -1.1; // Event timeStamp of the first transition. export let transitionEventType: null | string = null; // Event type of the first transition. export let transitionEventIsRepeat: boolean = false; +export let transitionSuspendedTime: number = -1.1; export function startUpdateTimerByLane(lane: Lane): void { if (!enableProfilerTimer || !enableComponentPerformanceTrack) { @@ -100,8 +102,20 @@ export function markUpdateAsRepeat(lanes: Lanes): void { } } +export function trackSuspendedTime(lanes: Lanes, renderEndTime: number) { + if (!enableProfilerTimer || !enableComponentPerformanceTrack) { + return; + } + if (includesSyncLane(lanes) || includesBlockingLane(lanes)) { + blockingSuspendedTime = renderEndTime; + } else if (includesTransitionLane(lanes)) { + transitionSuspendedTime = renderEndTime; + } +} + export function clearBlockingTimers(): void { blockingUpdateTime = -1.1; + blockingSuspendedTime = -1.1; } export function startAsyncTransitionTimer(): void { @@ -145,6 +159,7 @@ export function clearAsyncTransitionTimer(): void { export function clearTransitionTimers(): void { transitionStartTime = -1.1; transitionUpdateTime = -1.1; + transitionSuspendedTime = -1.1; } export function clampBlockingTimers(finalTime: number): void {