Log Render Phases that Never Committed (#31548)
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: <img width="893" alt="Screenshot 2024-11-14 at 11 47 40 PM" src="https://github.com/user-attachments/assets/b25a6a8b-a5e9-4d66-b325-57aef4bf9dad"> Errored with a second recovery attempt that also errors: <img width="976" alt="Screenshot 2024-11-15 at 12 09 06 AM" src="https://github.com/user-attachments/assets/9ce52cbb-b587-4f1e-8b67-e51d9073ae5b">
Sebastian Markbåge committed
Nov 15, 2024 at 12:13 UTC
3720870a979b48a1ea8776f64a190878b8558f2b
4 files changed
+121
-6
packages/react-reconciler/src/ReactFiberPerformanceTrack.js
+48
@@ -198,6 +198,54 @@ export function logRenderPhase(startTime: number, endTime: number): void {
198
}
199
}
200
201
+export function logInterruptedRenderPhase(
202
+ startTime: number,
203
+ endTime: number,
204
+): void {
205
+ if (supportsUserTiming) {
206
+ reusableLaneDevToolDetails.color = 'primary-dark';
207
+ reusableLaneOptions.start = startTime;
208
+ reusableLaneOptions.end = endTime;
209
+ performance.measure('Interrupted Render', reusableLaneOptions);
210
+ }
211
+}
212
+
213
+export function logSuspendedRenderPhase(
214
+ startTime: number,
215
+ endTime: number,
216
+): void {
217
+ if (supportsUserTiming) {
218
+ reusableLaneDevToolDetails.color = 'primary-dark';
219
+ reusableLaneOptions.start = startTime;
220
+ reusableLaneOptions.end = endTime;
221
+ performance.measure('Prewarm', reusableLaneOptions);
222
+ }
223
+}
224
+
225
+export function logErroredRenderPhase(
226
+ startTime: number,
227
+ endTime: number,
228
+): void {
229
+ if (supportsUserTiming) {
230
+ reusableLaneDevToolDetails.color = 'error';
231
+ reusableLaneOptions.start = startTime;
232
+ reusableLaneOptions.end = endTime;
233
+ performance.measure('Errored Render', reusableLaneOptions);
234
+ }
235
+}
236
+
237
+export function logInconsistentRender(
238
+ startTime: number,
239
+ endTime: number,
240
+): void {
241
+ if (supportsUserTiming) {
242
+ reusableLaneDevToolDetails.color = 'error';
243
+ reusableLaneOptions.start = startTime;
244
+ reusableLaneOptions.end = endTime;
245
+ performance.measure('Teared Render', reusableLaneOptions);
246
+ }
247
+}
248
+
249
export function logSuspenseThrottlePhase(
250
startTime: number,
251
endTime: number,
packages/react-reconciler/src/ReactFiberWorkLoop.js
+51
-3
@@ -69,6 +69,10 @@ import {
69
logBlockingStart,
70
logTransitionStart,
71
logRenderPhase,
72
+ logInterruptedRenderPhase,
73
+ logSuspendedRenderPhase,
74
+ logErroredRenderPhase,
75
+ logInconsistentRender,
76
logSuspenseThrottlePhase,
77
logSuspendedCommitPhase,
78
logCommitPhase,
@@ -255,6 +259,7 @@ import {
259
startProfilerTimer,
260
stopProfilerTimerIfRunningAndRecordDuration,
261
stopProfilerTimerIfRunningAndRecordIncompleteDuration,
262
+ markUpdateAsRepeat,
263
} from './ReactProfilerTimer';
264
import {setCurrentTrackFromLanes} from './ReactFiberPerformanceTrack';
265
@@ -955,6 +960,13 @@ export function performWorkOnRoot(
960
renderWasConcurrent &&
961
!isRenderConsistentWithExternalStores(finishedWork)
962
) {
963
+ if (enableProfilerTimer && enableComponentPerformanceTrack) {
964
+ setCurrentTrackFromLanes(lanes);
965
+ const renderEndTime = now();
966
+ logInconsistentRender(renderStartTime, renderEndTime);
967
+ finalizeRender(lanes, renderEndTime);
968
+ markUpdateAsRepeat(lanes);
969
+ }
970
// A store was mutated in an interleaved event. Render again,
971
// synchronously, to block further mutations.
972
exitStatus = renderRootSync(root, lanes, false);
@@ -976,6 +988,13 @@ export function performWorkOnRoot(
988
lanesThatJustErrored,
989
);
990
if (errorRetryLanes !== NoLanes) {
991
+ if (enableProfilerTimer && enableComponentPerformanceTrack) {
992
+ setCurrentTrackFromLanes(lanes);
993
+ const renderEndTime = now();
994
+ logErroredRenderPhase(renderStartTime, renderEndTime);
995
+ finalizeRender(lanes, renderEndTime);
996
+ markUpdateAsRepeat(lanes);
997
+ }
998
lanes = errorRetryLanes;
999
exitStatus = recoverFromConcurrentError(
1000
root,
@@ -999,6 +1018,12 @@ export function performWorkOnRoot(
1018
}
1019
}
1020
if (exitStatus === RootFatalErrored) {
1021
+ if (enableProfilerTimer && enableComponentPerformanceTrack) {
1022
+ setCurrentTrackFromLanes(lanes);
1023
+ const renderEndTime = now();
1024
+ logErroredRenderPhase(renderStartTime, renderEndTime);
1025
+ finalizeRender(lanes, renderEndTime);
1026
+ }
1027
prepareFreshStack(root, NoLanes);
1028
// Since this is a fatal error, we're going to pretend we attempted
1029
// the entire tree, to avoid scheduling a prerender.
@@ -1136,6 +1161,8 @@ function finishConcurrentRender(
1161
// placeholder and without scheduling a timeout. Delay indefinitely
1162
// until we receive more data.
1163
if (enableProfilerTimer && enableComponentPerformanceTrack) {
1164
+ setCurrentTrackFromLanes(lanes);
1165
+ logSuspendedRenderPhase(renderStartTime, renderEndTime);
1166
finalizeRender(lanes, renderEndTime);
1167
}
1168
const didAttemptEntireTree = !workInProgressRootDidSkipSuspendedSiblings;
@@ -1180,6 +1207,7 @@ function finishConcurrentRender(
1207
workInProgressDeferredLane,
1208
workInProgressRootInterleavedUpdatedLanes,
1209
workInProgressSuspendedRetryLanes,
1210
+ exitStatus,
1211
IMMEDIATE_COMMIT,
1212
renderStartTime,
1213
renderEndTime,
@@ -1230,6 +1258,7 @@ function finishConcurrentRender(
1258
workInProgressRootInterleavedUpdatedLanes,
1259
workInProgressSuspendedRetryLanes,
1260
workInProgressRootDidSkipSuspendedSiblings,
1261
+ exitStatus,
1262
THROTTLED_COMMIT,
1263
renderStartTime,
1264
renderEndTime,
@@ -1250,6 +1279,7 @@ function finishConcurrentRender(
1279
workInProgressRootInterleavedUpdatedLanes,
1280
workInProgressSuspendedRetryLanes,
1281
workInProgressRootDidSkipSuspendedSiblings,
1282
+ exitStatus,
1283
IMMEDIATE_COMMIT,
1284
renderStartTime,
1285
renderEndTime,
@@ -1268,6 +1298,7 @@ function commitRootWhenReady(
1298
updatedLanes: Lanes,
1299
suspendedRetryLanes: Lanes,
1300
didSkipSuspendedSiblings: boolean,
1301
+ exitStatus: RootExitStatus,
1302
suspendedCommitReason: SuspendedCommitReason, // Profiling-only
1303
completedRenderStartTime: number, // Profiling-only
1304
completedRenderEndTime: number, // Profiling-only
@@ -1311,6 +1342,7 @@ function commitRootWhenReady(
1342
spawnedLane,
1343
updatedLanes,
1344
suspendedRetryLanes,
1345
+ exitStatus,
1346
SUSPENDED_COMMIT,
1347
completedRenderStartTime,
1348
completedRenderEndTime,
@@ -1331,6 +1363,7 @@ function commitRootWhenReady(
1363
spawnedLane,
1364
updatedLanes,
1365
suspendedRetryLanes,
1366
+ exitStatus,
1367
suspendedCommitReason,
1368
completedRenderStartTime,
1369
completedRenderEndTime,
@@ -1649,13 +1682,21 @@ function finalizeRender(lanes: Lanes, finalizationTime: number): void {
1682
1683
function prepareFreshStack(root: FiberRoot, lanes: Lanes): Fiber {
1684
if (enableProfilerTimer && enableComponentPerformanceTrack) {
1685
+ const previousRenderStartTime = renderStartTime;
1686
// Starting a new render. Log the end of any previous renders and the
1687
// blocked time before the render started.
1688
recordRenderTime();
1689
// If this was a restart, e.g. due to an interrupting update, then there's no space
1690
// in the track to log the cause since we'll have rendered all the way up until the
1691
// restart so we need to clamp that.
1658
- finalizeRender(workInProgressRootRenderLanes, renderStartTime);
1692
+ if (
1693
+ workInProgressRootRenderLanes !== NoLanes &&
1694
+ previousRenderStartTime > 0
1695
+ ) {
1696
+ setCurrentTrackFromLanes(workInProgressRootRenderLanes);
1697
+ logInterruptedRenderPhase(previousRenderStartTime, renderStartTime);
1698
+ finalizeRender(workInProgressRootRenderLanes, renderStartTime);
1699
+ }
1700
1701
if (includesSyncLane(lanes) || includesBlockingLane(lanes)) {
1702
logBlockingStart(
@@ -2983,6 +3024,7 @@ function commitRoot(
3024
spawnedLane: Lane,
3025
updatedLanes: Lanes,
3026
suspendedRetryLanes: Lanes,
3027
+ exitStatus: RootExitStatus,
3028
suspendedCommitReason: SuspendedCommitReason, // Profiling-only
3029
completedRenderStartTime: number, // Profiling-only
3030
completedRenderEndTime: number, // Profiling-only
@@ -3003,6 +3045,7 @@ function commitRoot(
3045
spawnedLane,
3046
updatedLanes,
3047
suspendedRetryLanes,
3048
+ exitStatus,
3049
suspendedCommitReason,
3050
completedRenderStartTime,
3051
completedRenderEndTime,
@@ -3022,6 +3065,7 @@ function commitRootImpl(
3065
spawnedLane: Lane,
3066
updatedLanes: Lanes,
3067
suspendedRetryLanes: Lanes,
3068
+ exitStatus: RootExitStatus, // Profiling-only
3069
suspendedCommitReason: SuspendedCommitReason, // Profiling-only
3070
completedRenderStartTime: number, // Profiling-only
3071
completedRenderEndTime: number, // Profiling-only
@@ -3047,7 +3091,11 @@ function commitRootImpl(
3091
if (enableProfilerTimer && enableComponentPerformanceTrack) {
3092
// Log the previous render phase once we commit. I.e. we weren't interrupted.
3093
setCurrentTrackFromLanes(lanes);
3050
- logRenderPhase(completedRenderStartTime, completedRenderEndTime);
3094
+ if (exitStatus === RootErrored) {
3095
+ logErroredRenderPhase(completedRenderStartTime, completedRenderEndTime);
3096
+ } else {
3097
+ logRenderPhase(completedRenderStartTime, completedRenderEndTime);
3098
+ }
3099
}
3100
3101
if (__DEV__) {
@@ -3409,7 +3457,7 @@ function commitRootImpl(
3457
3458
if (enableProfilerTimer && enableComponentPerformanceTrack) {
3459
if (!rootDidHavePassiveEffects) {
3412
- finalizeRender(lanes, now());
3460
+ finalizeRender(lanes, commitEndTime);
3461
}
3462
}
3463
packages/react-reconciler/src/ReactProfilerTimer.js
+22
-2
@@ -9,8 +9,15 @@
9
10
import type {Fiber} from './ReactInternalTypes';
11
12
-import type {Lane} from './ReactFiberLane';
13
-import {isTransitionLane, isBlockingLane, isSyncLane} from './ReactFiberLane';
12
+import type {Lane, Lanes} from './ReactFiberLane';
13
+import {
14
+ isTransitionLane,
15
+ isBlockingLane,
16
+ isSyncLane,
17
+ includesTransitionLane,
18
+ includesBlockingLane,
19
+ includesSyncLane,
20
+} from './ReactFiberLane';
21
22
import {resolveEventType, resolveEventTimeStamp} from './ReactFiberConfig';
23
@@ -80,6 +87,19 @@ export function startUpdateTimerByLane(lane: Lane): void {
87
}
88
}
89
90
+export function markUpdateAsRepeat(lanes: Lanes): void {
91
+ if (!enableProfilerTimer || !enableComponentPerformanceTrack) {
92
+ return;
93
+ }
94
+ // We're about to do a retry of this render. It is not a new update, so treat this
95
+ // as a repeat within the same event.
96
+ if (includesSyncLane(lanes) || includesBlockingLane(lanes)) {
97
+ blockingEventIsRepeat = true;
98
+ } else if (includesTransitionLane(lanes)) {
99
+ transitionEventIsRepeat = true;
100
+ }
101
+}
102
+
103
export function clearBlockingTimers(): void {
104
blockingUpdateTime = -1.1;
105
}
packages/react/src/__tests__/ReactProfiler-test.internal.js
-1
@@ -181,7 +181,6 @@ describe(`onRender`, () => {
181
'read current time',
182
'read current time',
183
'read current time',
184
- 'read current time',
184
]);
185
} else {
186
assertLog([