From 3720870a979b48a1ea8776f64a190878b8558f2b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Sebastian=20Markb=C3=A5ge?= Date: Fri, 15 Nov 2024 12:13:24 -0500 Subject: [PATCH] Log Render Phases that Never Committed (#31548) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit This includes: - `Interrupted Render`: Interrupted Renders (setState or ping at higher priority) - `Prewarm`: Suspended Renders outside a Suspense boundary (RootSuspendedWithDelay/RootSuspendedAtTheShell) - `Errored Render`: Render that errored somewhere in the tree (Fatal or Not) (which may or may not be retried and then complete) - `Teared Render`: Due to useSyncExternalStore not matching (which will do another sync attempt) Suspended Commit: Screenshot 2024-11-14 at 11 47 40 PM Errored with a second recovery attempt that also errors: Screenshot 2024-11-15 at 12 09 06 AM --- .../src/ReactFiberPerformanceTrack.js | 48 +++++++++++++++++ .../src/ReactFiberWorkLoop.js | 54 +++++++++++++++++-- .../src/ReactProfilerTimer.js | 24 ++++++++- .../__tests__/ReactProfiler-test.internal.js | 1 - 4 files changed, 121 insertions(+), 6 deletions(-) diff --git a/packages/react-reconciler/src/ReactFiberPerformanceTrack.js b/packages/react-reconciler/src/ReactFiberPerformanceTrack.js index 859d5e6fa504a..f43d296a8ad61 100644 --- a/packages/react-reconciler/src/ReactFiberPerformanceTrack.js +++ b/packages/react-reconciler/src/ReactFiberPerformanceTrack.js @@ -198,6 +198,54 @@ export function logRenderPhase(startTime: number, endTime: number): void { } } +export function logInterruptedRenderPhase( + startTime: number, + endTime: number, +): void { + if (supportsUserTiming) { + reusableLaneDevToolDetails.color = 'primary-dark'; + reusableLaneOptions.start = startTime; + reusableLaneOptions.end = endTime; + performance.measure('Interrupted Render', reusableLaneOptions); + } +} + +export function logSuspendedRenderPhase( + startTime: number, + endTime: number, +): void { + if (supportsUserTiming) { + reusableLaneDevToolDetails.color = 'primary-dark'; + reusableLaneOptions.start = startTime; + reusableLaneOptions.end = endTime; + performance.measure('Prewarm', reusableLaneOptions); + } +} + +export function logErroredRenderPhase( + startTime: number, + endTime: number, +): void { + if (supportsUserTiming) { + reusableLaneDevToolDetails.color = 'error'; + reusableLaneOptions.start = startTime; + reusableLaneOptions.end = endTime; + performance.measure('Errored Render', reusableLaneOptions); + } +} + +export function logInconsistentRender( + startTime: number, + endTime: number, +): void { + if (supportsUserTiming) { + reusableLaneDevToolDetails.color = 'error'; + reusableLaneOptions.start = startTime; + reusableLaneOptions.end = endTime; + performance.measure('Teared Render', reusableLaneOptions); + } +} + export function logSuspenseThrottlePhase( startTime: number, endTime: number, diff --git a/packages/react-reconciler/src/ReactFiberWorkLoop.js b/packages/react-reconciler/src/ReactFiberWorkLoop.js index 4c20659b69cc0..7a5409a73559a 100644 --- a/packages/react-reconciler/src/ReactFiberWorkLoop.js +++ b/packages/react-reconciler/src/ReactFiberWorkLoop.js @@ -69,6 +69,10 @@ import { logBlockingStart, logTransitionStart, logRenderPhase, + logInterruptedRenderPhase, + logSuspendedRenderPhase, + logErroredRenderPhase, + logInconsistentRender, logSuspenseThrottlePhase, logSuspendedCommitPhase, logCommitPhase, @@ -255,6 +259,7 @@ import { startProfilerTimer, stopProfilerTimerIfRunningAndRecordDuration, stopProfilerTimerIfRunningAndRecordIncompleteDuration, + markUpdateAsRepeat, } from './ReactProfilerTimer'; import {setCurrentTrackFromLanes} from './ReactFiberPerformanceTrack'; @@ -955,6 +960,13 @@ export function performWorkOnRoot( renderWasConcurrent && !isRenderConsistentWithExternalStores(finishedWork) ) { + if (enableProfilerTimer && enableComponentPerformanceTrack) { + setCurrentTrackFromLanes(lanes); + const renderEndTime = now(); + logInconsistentRender(renderStartTime, renderEndTime); + finalizeRender(lanes, renderEndTime); + markUpdateAsRepeat(lanes); + } // A store was mutated in an interleaved event. Render again, // synchronously, to block further mutations. exitStatus = renderRootSync(root, lanes, false); @@ -976,6 +988,13 @@ export function performWorkOnRoot( lanesThatJustErrored, ); if (errorRetryLanes !== NoLanes) { + if (enableProfilerTimer && enableComponentPerformanceTrack) { + setCurrentTrackFromLanes(lanes); + const renderEndTime = now(); + logErroredRenderPhase(renderStartTime, renderEndTime); + finalizeRender(lanes, renderEndTime); + markUpdateAsRepeat(lanes); + } lanes = errorRetryLanes; exitStatus = recoverFromConcurrentError( root, @@ -999,6 +1018,12 @@ export function performWorkOnRoot( } } if (exitStatus === RootFatalErrored) { + if (enableProfilerTimer && enableComponentPerformanceTrack) { + setCurrentTrackFromLanes(lanes); + const renderEndTime = now(); + logErroredRenderPhase(renderStartTime, renderEndTime); + finalizeRender(lanes, renderEndTime); + } prepareFreshStack(root, NoLanes); // Since this is a fatal error, we're going to pretend we attempted // the entire tree, to avoid scheduling a prerender. @@ -1136,6 +1161,8 @@ function finishConcurrentRender( // placeholder and without scheduling a timeout. Delay indefinitely // until we receive more data. if (enableProfilerTimer && enableComponentPerformanceTrack) { + setCurrentTrackFromLanes(lanes); + logSuspendedRenderPhase(renderStartTime, renderEndTime); finalizeRender(lanes, renderEndTime); } const didAttemptEntireTree = !workInProgressRootDidSkipSuspendedSiblings; @@ -1180,6 +1207,7 @@ function finishConcurrentRender( workInProgressDeferredLane, workInProgressRootInterleavedUpdatedLanes, workInProgressSuspendedRetryLanes, + exitStatus, IMMEDIATE_COMMIT, renderStartTime, renderEndTime, @@ -1230,6 +1258,7 @@ function finishConcurrentRender( workInProgressRootInterleavedUpdatedLanes, workInProgressSuspendedRetryLanes, workInProgressRootDidSkipSuspendedSiblings, + exitStatus, THROTTLED_COMMIT, renderStartTime, renderEndTime, @@ -1250,6 +1279,7 @@ function finishConcurrentRender( workInProgressRootInterleavedUpdatedLanes, workInProgressSuspendedRetryLanes, workInProgressRootDidSkipSuspendedSiblings, + exitStatus, IMMEDIATE_COMMIT, renderStartTime, renderEndTime, @@ -1268,6 +1298,7 @@ function commitRootWhenReady( updatedLanes: Lanes, suspendedRetryLanes: Lanes, didSkipSuspendedSiblings: boolean, + exitStatus: RootExitStatus, suspendedCommitReason: SuspendedCommitReason, // Profiling-only completedRenderStartTime: number, // Profiling-only completedRenderEndTime: number, // Profiling-only @@ -1311,6 +1342,7 @@ function commitRootWhenReady( spawnedLane, updatedLanes, suspendedRetryLanes, + exitStatus, SUSPENDED_COMMIT, completedRenderStartTime, completedRenderEndTime, @@ -1331,6 +1363,7 @@ function commitRootWhenReady( spawnedLane, updatedLanes, suspendedRetryLanes, + exitStatus, suspendedCommitReason, completedRenderStartTime, completedRenderEndTime, @@ -1649,13 +1682,21 @@ function finalizeRender(lanes: Lanes, finalizationTime: number): void { function prepareFreshStack(root: FiberRoot, lanes: Lanes): Fiber { if (enableProfilerTimer && enableComponentPerformanceTrack) { + const previousRenderStartTime = renderStartTime; // 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 ( + workInProgressRootRenderLanes !== NoLanes && + previousRenderStartTime > 0 + ) { + setCurrentTrackFromLanes(workInProgressRootRenderLanes); + logInterruptedRenderPhase(previousRenderStartTime, renderStartTime); + finalizeRender(workInProgressRootRenderLanes, renderStartTime); + } if (includesSyncLane(lanes) || includesBlockingLane(lanes)) { logBlockingStart( @@ -2983,6 +3024,7 @@ function commitRoot( spawnedLane: Lane, updatedLanes: Lanes, suspendedRetryLanes: Lanes, + exitStatus: RootExitStatus, suspendedCommitReason: SuspendedCommitReason, // Profiling-only completedRenderStartTime: number, // Profiling-only completedRenderEndTime: number, // Profiling-only @@ -3003,6 +3045,7 @@ function commitRoot( spawnedLane, updatedLanes, suspendedRetryLanes, + exitStatus, suspendedCommitReason, completedRenderStartTime, completedRenderEndTime, @@ -3022,6 +3065,7 @@ function commitRootImpl( spawnedLane: Lane, updatedLanes: Lanes, suspendedRetryLanes: Lanes, + exitStatus: RootExitStatus, // Profiling-only suspendedCommitReason: SuspendedCommitReason, // Profiling-only completedRenderStartTime: number, // Profiling-only completedRenderEndTime: number, // Profiling-only @@ -3047,7 +3091,11 @@ function commitRootImpl( if (enableProfilerTimer && enableComponentPerformanceTrack) { // Log the previous render phase once we commit. I.e. we weren't interrupted. setCurrentTrackFromLanes(lanes); - logRenderPhase(completedRenderStartTime, completedRenderEndTime); + if (exitStatus === RootErrored) { + logErroredRenderPhase(completedRenderStartTime, completedRenderEndTime); + } else { + logRenderPhase(completedRenderStartTime, completedRenderEndTime); + } } if (__DEV__) { @@ -3409,7 +3457,7 @@ function commitRootImpl( if (enableProfilerTimer && enableComponentPerformanceTrack) { if (!rootDidHavePassiveEffects) { - finalizeRender(lanes, now()); + finalizeRender(lanes, commitEndTime); } } diff --git a/packages/react-reconciler/src/ReactProfilerTimer.js b/packages/react-reconciler/src/ReactProfilerTimer.js index 93869c85148a8..87d7c0324bcb5 100644 --- a/packages/react-reconciler/src/ReactProfilerTimer.js +++ b/packages/react-reconciler/src/ReactProfilerTimer.js @@ -9,8 +9,15 @@ import type {Fiber} from './ReactInternalTypes'; -import type {Lane} from './ReactFiberLane'; -import {isTransitionLane, isBlockingLane, isSyncLane} from './ReactFiberLane'; +import type {Lane, Lanes} from './ReactFiberLane'; +import { + isTransitionLane, + isBlockingLane, + isSyncLane, + includesTransitionLane, + includesBlockingLane, + includesSyncLane, +} from './ReactFiberLane'; import {resolveEventType, resolveEventTimeStamp} from './ReactFiberConfig'; @@ -80,6 +87,19 @@ export function startUpdateTimerByLane(lane: Lane): void { } } +export function markUpdateAsRepeat(lanes: Lanes): void { + if (!enableProfilerTimer || !enableComponentPerformanceTrack) { + return; + } + // We're about to do a retry of this render. It is not a new update, so treat this + // as a repeat within the same event. + if (includesSyncLane(lanes) || includesBlockingLane(lanes)) { + blockingEventIsRepeat = true; + } else if (includesTransitionLane(lanes)) { + transitionEventIsRepeat = true; + } +} + export function clearBlockingTimers(): void { blockingUpdateTime = -1.1; } diff --git a/packages/react/src/__tests__/ReactProfiler-test.internal.js b/packages/react/src/__tests__/ReactProfiler-test.internal.js index 522c3a11cf29d..eb46f5b33a4ce 100644 --- a/packages/react/src/__tests__/ReactProfiler-test.internal.js +++ b/packages/react/src/__tests__/ReactProfiler-test.internal.js @@ -181,7 +181,6 @@ describe(`onRender`, () => { 'read current time', 'read current time', 'read current time', - 'read current time', ]); } else { assertLog([