Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Log Render Phases that Never Committed #31548

Merged
merged 4 commits into from
Nov 15, 2024
+121 −6
Merged

Log Render Phases that Never Committed #31548

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
ffcc59b
Log interrupted or suspended renders
sebmarkbage Nov 15, 2024
cc3c9b9
Log errored render phases
sebmarkbage Nov 15, 2024
6e075d3
Mark repeat attempts as updates within the same event rather than a n…
sebmarkbage Nov 15, 2024
d88bf01
Update test. One less read.
sebmarkbage Nov 15, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
48 changes: 48 additions & 0 deletions packages/react-reconciler/src/ReactFiberPerformanceTrack.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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';
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Isn't an inconsistent render more similar to an interrupted render? It's not really an error if that happens, no?

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The issue here is that it causes a synchronous render (from a transition) so it's more similar to a recoverable error. In fact, a recoverable error from concurrent is the same concept. An interrupted render doesn't have that issue since it'll be async in the update too.

This shows a downside of using a mutable store over an immutable one.

reusableLaneOptions.start = startTime;
reusableLaneOptions.end = endTime;
performance.measure('Teared Render', reusableLaneOptions);
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

PR description says "inconsistent" but here we use "teared". I like "teared" more since that's what we used before: reactwg/react-18#69. "tearing" is also easier to google for whereas "inconsistent" is too generic but maybe that's what we need here?

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I updated PR description. I just used inconsistent for the function name since that’s what it is called in the internals for now.

}
}

export function logSuspenseThrottlePhase(
startTime: number,
endTime: number,
Expand Down
54 changes: 51 additions & 3 deletions packages/react-reconciler/src/ReactFiberWorkLoop.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -69,6 +69,10 @@ import {
logBlockingStart,
logTransitionStart,
logRenderPhase,
logInterruptedRenderPhase,
logSuspendedRenderPhase,
logErroredRenderPhase,
logInconsistentRender,
logSuspenseThrottlePhase,
logSuspendedCommitPhase,
logCommitPhase,
Expand Down Expand Up @@ -255,6 +259,7 @@ import {
startProfilerTimer,
stopProfilerTimerIfRunningAndRecordDuration,
stopProfilerTimerIfRunningAndRecordIncompleteDuration,
markUpdateAsRepeat,
} from './ReactProfilerTimer';
import {setCurrentTrackFromLanes} from './ReactFiberPerformanceTrack';

Expand Down Expand Up @@ -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);
Expand All @@ -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,
Expand All @@ -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.
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -1180,6 +1207,7 @@ function finishConcurrentRender(
workInProgressDeferredLane,
workInProgressRootInterleavedUpdatedLanes,
workInProgressSuspendedRetryLanes,
exitStatus,
IMMEDIATE_COMMIT,
renderStartTime,
renderEndTime,
Expand Down Expand Up @@ -1230,6 +1258,7 @@ function finishConcurrentRender(
workInProgressRootInterleavedUpdatedLanes,
workInProgressSuspendedRetryLanes,
workInProgressRootDidSkipSuspendedSiblings,
exitStatus,
THROTTLED_COMMIT,
renderStartTime,
renderEndTime,
Expand All @@ -1250,6 +1279,7 @@ function finishConcurrentRender(
workInProgressRootInterleavedUpdatedLanes,
workInProgressSuspendedRetryLanes,
workInProgressRootDidSkipSuspendedSiblings,
exitStatus,
IMMEDIATE_COMMIT,
renderStartTime,
renderEndTime,
Expand All @@ -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
Expand Down Expand Up @@ -1311,6 +1342,7 @@ function commitRootWhenReady(
spawnedLane,
updatedLanes,
suspendedRetryLanes,
exitStatus,
SUSPENDED_COMMIT,
completedRenderStartTime,
completedRenderEndTime,
Expand All @@ -1331,6 +1363,7 @@ function commitRootWhenReady(
spawnedLane,
updatedLanes,
suspendedRetryLanes,
exitStatus,
suspendedCommitReason,
completedRenderStartTime,
completedRenderEndTime,
Expand Down Expand Up @@ -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(
Expand Down Expand Up @@ -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
Expand All @@ -3003,6 +3045,7 @@ function commitRoot(
spawnedLane,
updatedLanes,
suspendedRetryLanes,
exitStatus,
suspendedCommitReason,
completedRenderStartTime,
completedRenderEndTime,
Expand All @@ -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
Expand All @@ -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__) {
Expand Down Expand Up @@ -3409,7 +3457,7 @@ function commitRootImpl(

if (enableProfilerTimer && enableComponentPerformanceTrack) {
if (!rootDidHavePassiveEffects) {
finalizeRender(lanes, now());
finalizeRender(lanes, commitEndTime);
}
}

Expand Down
24 changes: 22 additions & 2 deletions packages/react-reconciler/src/ReactProfilerTimer.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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';

Expand Down Expand Up @@ -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;
}
Expand Down
1 change: 0 additions & 1 deletion packages/react/src/__tests__/ReactProfiler-test.internal.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -181,7 +181,6 @@ describe(`onRender`, () => {
'read current time',
'read current time',
'read current time',
'read current time',
]);
} else {
assertLog([
Expand Down
Loading