Track suspended time when the render doesn't commit because it suspended (#31552)
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. <img width="902" alt="Screenshot 2024-11-15 at 1 01 29 PM" src="https://github.com/user-attachments/assets/acf9dc9a-8fc3-4367-a8b0-d19f9c9eac73"> 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.
Sebastian Markbåge committed
Nov 19, 2024 at 13:42 UTC
6177b18c66c010d2b2f03202623a0533e7a89004
3 files changed
+90
-18
packages/react-reconciler/src/ReactFiberPerformanceTrack.js
+13
@@ -222,6 +222,19 @@ export function logSuspendedRenderPhase(
222
}
223
}
224
225
+export function logSuspendedWithDelayPhase(
226
+ startTime: number,
227
+ endTime: number,
228
+): void {
229
+ // This means the render was suspended and cannot commit until it gets unblocked.
230
+ if (supportsUserTiming) {
231
+ reusableLaneDevToolDetails.color = 'primary-dark';
232
+ reusableLaneOptions.start = startTime;
233
+ reusableLaneOptions.end = endTime;
234
+ performance.measure('Suspended', reusableLaneOptions);
235
+ }
236
+}
237
+
238
export function logErroredRenderPhase(
239
startTime: number,
240
endTime: number,
packages/react-reconciler/src/ReactFiberWorkLoop.js
+62
-18
@@ -73,6 +73,7 @@ import {
73
logSuspendedRenderPhase,
74
logErroredRenderPhase,
75
logInconsistentRender,
76
+ logSuspendedWithDelayPhase,
77
logSuspenseThrottlePhase,
78
logSuspendedCommitPhase,
79
logCommitPhase,
@@ -239,12 +240,14 @@ import {
240
blockingEventTime,
241
blockingEventType,
242
blockingEventIsRepeat,
243
+ blockingSuspendedTime,
244
transitionClampTime,
245
transitionStartTime,
246
transitionUpdateTime,
247
transitionEventTime,
248
transitionEventType,
249
transitionEventIsRepeat,
250
+ transitionSuspendedTime,
251
clearBlockingTimers,
252
clearTransitionTimers,
253
clampBlockingTimers,
@@ -260,6 +263,7 @@ import {
263
stopProfilerTimerIfRunningAndRecordDuration,
264
stopProfilerTimerIfRunningAndRecordIncompleteDuration,
265
markUpdateAsRepeat,
266
+ trackSuspendedTime,
267
} from './ReactProfilerTimer';
268
import {setCurrentTrackFromLanes} from './ReactFiberPerformanceTrack';
269
@@ -954,6 +958,11 @@ export function performWorkOnRoot(
958
}
959
break;
960
} else {
961
+ let renderEndTime = 0;
962
+ if (enableProfilerTimer && enableComponentPerformanceTrack) {
963
+ renderEndTime = now();
964
+ }
965
+
966
// The render completed.
967
968
// Check if this render may have yielded to a concurrent event, and if so,
@@ -968,7 +977,6 @@ export function performWorkOnRoot(
977
) {
978
if (enableProfilerTimer && enableComponentPerformanceTrack) {
979
setCurrentTrackFromLanes(lanes);
971
- const renderEndTime = now();
980
logInconsistentRender(renderStartTime, renderEndTime);
981
finalizeRender(lanes, renderEndTime);
982
markUpdateAsRepeat(lanes);
@@ -996,7 +1004,6 @@ export function performWorkOnRoot(
1004
if (errorRetryLanes !== NoLanes) {
1005
if (enableProfilerTimer && enableComponentPerformanceTrack) {
1006
setCurrentTrackFromLanes(lanes);
999
- const renderEndTime = now();
1007
logErroredRenderPhase(renderStartTime, renderEndTime);
1008
finalizeRender(lanes, renderEndTime);
1009
markUpdateAsRepeat(lanes);
@@ -1020,13 +1027,15 @@ export function performWorkOnRoot(
1027
continue;
1028
} else {
1029
// The root errored yet again. Proceed to commit the tree.
1030
+ if (enableProfilerTimer && enableComponentPerformanceTrack) {
1031
+ renderEndTime = now();
1032
+ }
1033
}
1034
}
1035
}
1036
if (exitStatus === RootFatalErrored) {
1037
if (enableProfilerTimer && enableComponentPerformanceTrack) {
1038
setCurrentTrackFromLanes(lanes);
1029
- const renderEndTime = now();
1039
logErroredRenderPhase(renderStartTime, renderEndTime);
1040
finalizeRender(lanes, renderEndTime);
1041
}
@@ -1040,7 +1049,13 @@ export function performWorkOnRoot(
1049
1050
// We now have a consistent tree. The next step is either to commit it,
1051
// or, if something suspended, wait to commit it after a timeout.
1043
- finishConcurrentRender(root, exitStatus, finishedWork, lanes);
1052
+ finishConcurrentRender(
1053
+ root,
1054
+ exitStatus,
1055
+ finishedWork,
1056
+ lanes,
1057
+ renderEndTime,
1058
+ );
1059
}
1060
break;
1061
} while (true);
@@ -1139,14 +1154,8 @@ function finishConcurrentRender(
1154
exitStatus: RootExitStatus,
1155
finishedWork: Fiber,
1156
lanes: Lanes,
1157
+ renderEndTime: number, // Profiling-only
1158
) {
1143
- let renderEndTime = 0;
1144
- if (enableProfilerTimer && enableComponentPerformanceTrack) {
1145
- // Track when we finished the last unit of work, before we actually commit it.
1146
- // The commit can be suspended/blocked until we commit it.
1147
- renderEndTime = now();
1148
- }
1149
-
1159
// TODO: The fact that most of these branches are identical suggests that some
1160
// of the exit statuses are not best modeled as exit statuses and should be
1161
// tracked orthogonally.
@@ -1170,6 +1179,7 @@ function finishConcurrentRender(
1179
setCurrentTrackFromLanes(lanes);
1180
logSuspendedRenderPhase(renderStartTime, renderEndTime);
1181
finalizeRender(lanes, renderEndTime);
1182
+ trackSuspendedTime(lanes, renderEndTime);
1183
}
1184
const didAttemptEntireTree = !workInProgressRootDidSkipSuspendedSiblings;
1185
markRootSuspended(
@@ -1705,13 +1715,29 @@ function prepareFreshStack(root: FiberRoot, lanes: Lanes): Fiber {
1715
}
1716
1717
if (includesSyncLane(lanes) || includesBlockingLane(lanes)) {
1708
- logBlockingStart(
1718
+ const clampedUpdateTime =
1719
blockingUpdateTime >= 0 && blockingUpdateTime < blockingClampTime
1720
? blockingClampTime
1711
- : blockingUpdateTime,
1721
+ : blockingUpdateTime;
1722
+ const clampedEventTime =
1723
blockingEventTime >= 0 && blockingEventTime < blockingClampTime
1724
? blockingClampTime
1714
- : blockingEventTime,
1725
+ : blockingEventTime;
1726
+ if (blockingSuspendedTime >= 0) {
1727
+ setCurrentTrackFromLanes(lanes);
1728
+ logSuspendedWithDelayPhase(
1729
+ blockingSuspendedTime,
1730
+ // Clamp the suspended time to the first event/update.
1731
+ clampedEventTime >= 0
1732
+ ? clampedEventTime
1733
+ : clampedUpdateTime >= 0
1734
+ ? clampedUpdateTime
1735
+ : renderStartTime,
1736
+ );
1737
+ }
1738
+ logBlockingStart(
1739
+ clampedUpdateTime,
1740
+ clampedEventTime,
1741
blockingEventType,
1742
blockingEventIsRepeat,
1743
renderStartTime,
@@ -1719,16 +1745,34 @@ function prepareFreshStack(root: FiberRoot, lanes: Lanes): Fiber {
1745
clearBlockingTimers();
1746
}
1747
if (includesTransitionLane(lanes)) {
1722
- logTransitionStart(
1748
+ const clampedStartTime =
1749
transitionStartTime >= 0 && transitionStartTime < transitionClampTime
1750
? transitionClampTime
1725
- : transitionStartTime,
1751
+ : transitionStartTime;
1752
+ const clampedUpdateTime =
1753
transitionUpdateTime >= 0 && transitionUpdateTime < transitionClampTime
1754
? transitionClampTime
1728
- : transitionUpdateTime,
1755
+ : transitionUpdateTime;
1756
+ const clampedEventTime =
1757
transitionEventTime >= 0 && transitionEventTime < transitionClampTime
1758
? transitionClampTime
1731
- : transitionEventTime,
1759
+ : transitionEventTime;
1760
+ if (transitionSuspendedTime >= 0) {
1761
+ setCurrentTrackFromLanes(lanes);
1762
+ logSuspendedWithDelayPhase(
1763
+ transitionSuspendedTime,
1764
+ // Clamp the suspended time to the first event/update.
1765
+ clampedEventTime >= 0
1766
+ ? clampedEventTime
1767
+ : clampedUpdateTime >= 0
1768
+ ? clampedUpdateTime
1769
+ : renderStartTime,
1770
+ );
1771
+ }
1772
+ logTransitionStart(
1773
+ clampedStartTime,
1774
+ clampedUpdateTime,
1775
+ clampedEventTime,
1776
transitionEventType,
1777
transitionEventIsRepeat,
1778
renderStartTime,
packages/react-reconciler/src/ReactProfilerTimer.js
+15
@@ -48,6 +48,7 @@ export let blockingUpdateTime: number = -1.1; // First sync setState scheduled.
48
export let blockingEventTime: number = -1.1; // Event timeStamp of the first setState.
49
export let blockingEventType: null | string = null; // Event type of the first setState.
50
export let blockingEventIsRepeat: boolean = false;
51
+export let blockingSuspendedTime: number = -1.1;
52
// TODO: This should really be one per Transition lane.
53
export let transitionClampTime: number = -0;
54
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
56
export let transitionEventTime: number = -1.1; // Event timeStamp of the first transition.
57
export let transitionEventType: null | string = null; // Event type of the first transition.
58
export let transitionEventIsRepeat: boolean = false;
59
+export let transitionSuspendedTime: number = -1.1;
60
61
export function startUpdateTimerByLane(lane: Lane): void {
62
if (!enableProfilerTimer || !enableComponentPerformanceTrack) {
@@ -100,8 +102,20 @@ export function markUpdateAsRepeat(lanes: Lanes): void {
102
}
103
}
104
105
+export function trackSuspendedTime(lanes: Lanes, renderEndTime: number) {
106
+ if (!enableProfilerTimer || !enableComponentPerformanceTrack) {
107
+ return;
108
+ }
109
+ if (includesSyncLane(lanes) || includesBlockingLane(lanes)) {
110
+ blockingSuspendedTime = renderEndTime;
111
+ } else if (includesTransitionLane(lanes)) {
112
+ transitionSuspendedTime = renderEndTime;
113
+ }
114
+}
115
+
116
export function clearBlockingTimers(): void {
117
blockingUpdateTime = -1.1;
118
+ blockingSuspendedTime = -1.1;
119
}
120
121
export function startAsyncTransitionTimer(): void {
@@ -145,6 +159,7 @@ export function clearAsyncTransitionTimer(): void {
159
export function clearTransitionTimers(): void {
160
transitionStartTime = -1.1;
161
transitionUpdateTime = -1.1;
162
+ transitionSuspendedTime = -1.1;
163
}
164
165
export function clampBlockingTimers(finalTime: number): void {