From ffcc59be1a34dbbd38d483bfb723340ac510e306 Mon Sep 17 00:00:00 2001 From: Sebastian Markbage Date: Thu, 14 Nov 2024 21:36:35 -0500 Subject: [PATCH 1/4] Log interrupted or suspended renders --- .../src/ReactFiberPerformanceTrack.js | 24 +++++++++++++++++++ .../src/ReactFiberWorkLoop.js | 14 ++++++++++- 2 files changed, 37 insertions(+), 1 deletion(-) diff --git a/packages/react-reconciler/src/ReactFiberPerformanceTrack.js b/packages/react-reconciler/src/ReactFiberPerformanceTrack.js index 859d5e6fa504..c2b345fa660a 100644 --- a/packages/react-reconciler/src/ReactFiberPerformanceTrack.js +++ b/packages/react-reconciler/src/ReactFiberPerformanceTrack.js @@ -198,6 +198,30 @@ 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 logSuspenseThrottlePhase( startTime: number, endTime: number, diff --git a/packages/react-reconciler/src/ReactFiberWorkLoop.js b/packages/react-reconciler/src/ReactFiberWorkLoop.js index 4c20659b69cc..f08a2a57c9e1 100644 --- a/packages/react-reconciler/src/ReactFiberWorkLoop.js +++ b/packages/react-reconciler/src/ReactFiberWorkLoop.js @@ -69,6 +69,8 @@ import { logBlockingStart, logTransitionStart, logRenderPhase, + logInterruptedRenderPhase, + logSuspendedRenderPhase, logSuspenseThrottlePhase, logSuspendedCommitPhase, logCommitPhase, @@ -1136,6 +1138,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; @@ -1649,13 +1653,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( From cc3c9b96a3268eac49b8ba9f190b7704c98a8a30 Mon Sep 17 00:00:00 2001 From: Sebastian Markbage Date: Thu, 14 Nov 2024 23:35:44 -0500 Subject: [PATCH 2/4] Log errored render phases --- .../src/ReactFiberPerformanceTrack.js | 24 ++++++++++++ .../src/ReactFiberWorkLoop.js | 37 ++++++++++++++++++- 2 files changed, 59 insertions(+), 2 deletions(-) diff --git a/packages/react-reconciler/src/ReactFiberPerformanceTrack.js b/packages/react-reconciler/src/ReactFiberPerformanceTrack.js index c2b345fa660a..f43d296a8ad6 100644 --- a/packages/react-reconciler/src/ReactFiberPerformanceTrack.js +++ b/packages/react-reconciler/src/ReactFiberPerformanceTrack.js @@ -222,6 +222,30 @@ export function logSuspendedRenderPhase( } } +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 f08a2a57c9e1..de8dc9e27f15 100644 --- a/packages/react-reconciler/src/ReactFiberWorkLoop.js +++ b/packages/react-reconciler/src/ReactFiberWorkLoop.js @@ -71,6 +71,8 @@ import { logRenderPhase, logInterruptedRenderPhase, logSuspendedRenderPhase, + logErroredRenderPhase, + logInconsistentRender, logSuspenseThrottlePhase, logSuspendedCommitPhase, logCommitPhase, @@ -957,6 +959,12 @@ export function performWorkOnRoot( renderWasConcurrent && !isRenderConsistentWithExternalStores(finishedWork) ) { + if (enableProfilerTimer && enableComponentPerformanceTrack) { + setCurrentTrackFromLanes(lanes); + const renderEndTime = now(); + logInconsistentRender(renderStartTime, renderEndTime); + finalizeRender(lanes, renderEndTime); + } // A store was mutated in an interleaved event. Render again, // synchronously, to block further mutations. exitStatus = renderRootSync(root, lanes, false); @@ -978,6 +986,12 @@ export function performWorkOnRoot( lanesThatJustErrored, ); if (errorRetryLanes !== NoLanes) { + if (enableProfilerTimer && enableComponentPerformanceTrack) { + setCurrentTrackFromLanes(lanes); + const renderEndTime = now(); + logErroredRenderPhase(renderStartTime, renderEndTime); + finalizeRender(lanes, renderEndTime); + } lanes = errorRetryLanes; exitStatus = recoverFromConcurrentError( root, @@ -1001,6 +1015,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. @@ -1184,6 +1204,7 @@ function finishConcurrentRender( workInProgressDeferredLane, workInProgressRootInterleavedUpdatedLanes, workInProgressSuspendedRetryLanes, + exitStatus, IMMEDIATE_COMMIT, renderStartTime, renderEndTime, @@ -1234,6 +1255,7 @@ function finishConcurrentRender( workInProgressRootInterleavedUpdatedLanes, workInProgressSuspendedRetryLanes, workInProgressRootDidSkipSuspendedSiblings, + exitStatus, THROTTLED_COMMIT, renderStartTime, renderEndTime, @@ -1254,6 +1276,7 @@ function finishConcurrentRender( workInProgressRootInterleavedUpdatedLanes, workInProgressSuspendedRetryLanes, workInProgressRootDidSkipSuspendedSiblings, + exitStatus, IMMEDIATE_COMMIT, renderStartTime, renderEndTime, @@ -1272,6 +1295,7 @@ function commitRootWhenReady( updatedLanes: Lanes, suspendedRetryLanes: Lanes, didSkipSuspendedSiblings: boolean, + exitStatus: RootExitStatus, suspendedCommitReason: SuspendedCommitReason, // Profiling-only completedRenderStartTime: number, // Profiling-only completedRenderEndTime: number, // Profiling-only @@ -1315,6 +1339,7 @@ function commitRootWhenReady( spawnedLane, updatedLanes, suspendedRetryLanes, + exitStatus, SUSPENDED_COMMIT, completedRenderStartTime, completedRenderEndTime, @@ -1335,6 +1360,7 @@ function commitRootWhenReady( spawnedLane, updatedLanes, suspendedRetryLanes, + exitStatus, suspendedCommitReason, completedRenderStartTime, completedRenderEndTime, @@ -2995,6 +3021,7 @@ function commitRoot( spawnedLane: Lane, updatedLanes: Lanes, suspendedRetryLanes: Lanes, + exitStatus: RootExitStatus, suspendedCommitReason: SuspendedCommitReason, // Profiling-only completedRenderStartTime: number, // Profiling-only completedRenderEndTime: number, // Profiling-only @@ -3015,6 +3042,7 @@ function commitRoot( spawnedLane, updatedLanes, suspendedRetryLanes, + exitStatus, suspendedCommitReason, completedRenderStartTime, completedRenderEndTime, @@ -3034,6 +3062,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 @@ -3059,7 +3088,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__) { @@ -3421,7 +3454,7 @@ function commitRootImpl( if (enableProfilerTimer && enableComponentPerformanceTrack) { if (!rootDidHavePassiveEffects) { - finalizeRender(lanes, now()); + finalizeRender(lanes, commitEndTime); } } From 6e075d35f646fd8f524c247a40a0a02b7537da2e Mon Sep 17 00:00:00 2001 From: Sebastian Markbage Date: Fri, 15 Nov 2024 00:05:12 -0500 Subject: [PATCH 3/4] Mark repeat attempts as updates within the same event rather than a new event --- .../src/ReactFiberWorkLoop.js | 3 +++ .../src/ReactProfilerTimer.js | 24 +++++++++++++++++-- 2 files changed, 25 insertions(+), 2 deletions(-) diff --git a/packages/react-reconciler/src/ReactFiberWorkLoop.js b/packages/react-reconciler/src/ReactFiberWorkLoop.js index de8dc9e27f15..7a5409a73559 100644 --- a/packages/react-reconciler/src/ReactFiberWorkLoop.js +++ b/packages/react-reconciler/src/ReactFiberWorkLoop.js @@ -259,6 +259,7 @@ import { startProfilerTimer, stopProfilerTimerIfRunningAndRecordDuration, stopProfilerTimerIfRunningAndRecordIncompleteDuration, + markUpdateAsRepeat, } from './ReactProfilerTimer'; import {setCurrentTrackFromLanes} from './ReactFiberPerformanceTrack'; @@ -964,6 +965,7 @@ export function performWorkOnRoot( 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. @@ -991,6 +993,7 @@ export function performWorkOnRoot( const renderEndTime = now(); logErroredRenderPhase(renderStartTime, renderEndTime); finalizeRender(lanes, renderEndTime); + markUpdateAsRepeat(lanes); } lanes = errorRetryLanes; exitStatus = recoverFromConcurrentError( diff --git a/packages/react-reconciler/src/ReactProfilerTimer.js b/packages/react-reconciler/src/ReactProfilerTimer.js index 93869c85148a..87d7c0324bcb 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; } From d88bf012fb66ff26d8f3936c45e10e669c61841d Mon Sep 17 00:00:00 2001 From: Sebastian Markbage Date: Fri, 15 Nov 2024 00:18:17 -0500 Subject: [PATCH 4/4] Update test. One less read. --- packages/react/src/__tests__/ReactProfiler-test.internal.js | 1 - 1 file changed, 1 deletion(-) diff --git a/packages/react/src/__tests__/ReactProfiler-test.internal.js b/packages/react/src/__tests__/ReactProfiler-test.internal.js index 522c3a11cf29..eb46f5b33a4c 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([