Log yielded time in the Component Track (#31563)
Stacked on #31552. Must be tested with `enableSiblingPrerendering` off since the `use()` optimization is not on there yet. This adds a span to the Components track when we yield in the middle of the event loop. In this scenario, the "Render" span continues through out the Scheduler track. So you can see that the Component itself might not take a long time but yielding inside of it might. This lets you see if something was blocking the React render loop while yielding. If we're blocked 1ms or longer we log that as "Blocked". If we're yielding due to suspending in the middle of the work loop we log this as "Suspended". <img width="837" alt="Screenshot 2024-11-16 at 1 15 14 PM" src="https://github.com/user-attachments/assets/45a858ea-17e6-416c-af1a-78c126e033f3"> If the render doesn't commit because it restarts due to some other prewarming or because some non-`use()` suspends, it doesn't have from context components. <img width="971" alt="Screenshot 2024-11-16 at 1 13 55 PM" src="https://github.com/user-attachments/assets/a67724f8-702e-4e7d-9499-9ffc09541a61"> The `useActionState` path doesn't work yet because the `use()` optimization doesn't work there for some reason. But the idea is that it should mark the time that the component is blocked as Action instead of Suspended.
Sebastian Markbåge committed
Nov 19, 2024 at 13:56 UTC
7c254b65761c56951a67d965461b0174f224a7e9
3 files changed
+92
-1
packages/react-reconciler/src/ReactFiberPerformanceTrack.js
+48
@@ -114,6 +114,54 @@ export function logComponentEffect(
114
}
115
}
116
117
+export function logYieldTime(startTime: number, endTime: number): void {
118
+ if (supportsUserTiming) {
119
+ const yieldDuration = endTime - startTime;
120
+ if (yieldDuration < 1) {
121
+ // Skip sub-millisecond yields. This happens all the time and is not interesting.
122
+ return;
123
+ }
124
+ // Being blocked on CPU is potentially bad so we color it by how long it took.
125
+ reusableComponentDevToolDetails.color =
126
+ yieldDuration < 5
127
+ ? 'primary-light'
128
+ : yieldDuration < 10
129
+ ? 'primary'
130
+ : yieldDuration < 100
131
+ ? 'primary-dark'
132
+ : 'error';
133
+ reusableComponentOptions.start = startTime;
134
+ reusableComponentOptions.end = endTime;
135
+ performance.measure('Blocked', reusableComponentOptions);
136
+ }
137
+}
138
+
139
+export function logSuspendedYieldTime(
140
+ startTime: number,
141
+ endTime: number,
142
+ suspendedFiber: Fiber,
143
+): void {
144
+ if (supportsUserTiming) {
145
+ reusableComponentDevToolDetails.color = 'primary-light';
146
+ reusableComponentOptions.start = startTime;
147
+ reusableComponentOptions.end = endTime;
148
+ performance.measure('Suspended', reusableComponentOptions);
149
+ }
150
+}
151
+
152
+export function logActionYieldTime(
153
+ startTime: number,
154
+ endTime: number,
155
+ suspendedFiber: Fiber,
156
+): void {
157
+ if (supportsUserTiming) {
158
+ reusableComponentDevToolDetails.color = 'primary-light';
159
+ reusableComponentOptions.start = startTime;
160
+ reusableComponentOptions.end = endTime;
161
+ performance.measure('Action', reusableComponentOptions);
162
+ }
163
+}
164
+
165
export function logBlockingStart(
166
updateTime: number,
167
eventTime: number,
packages/react-reconciler/src/ReactFiberWorkLoop.js
+31
-1
@@ -79,6 +79,9 @@ import {
79
logCommitPhase,
80
logPaintYieldPhase,
81
logPassiveCommitPhase,
82
+ logYieldTime,
83
+ logActionYieldTime,
84
+ logSuspendedYieldTime,
85
} from './ReactFiberPerformanceTrack';
86
87
import {
@@ -264,6 +267,9 @@ import {
267
stopProfilerTimerIfRunningAndRecordIncompleteDuration,
268
markUpdateAsRepeat,
269
trackSuspendedTime,
270
+ startYieldTimer,
271
+ yieldStartTime,
272
+ yieldReason,
273
} from './ReactProfilerTimer';
274
import {setCurrentTrackFromLanes} from './ReactFiberPerformanceTrack';
275
@@ -351,7 +357,7 @@ let workInProgress: Fiber | null = null;
357
// The lanes we're rendering
358
let workInProgressRootRenderLanes: Lanes = NoLanes;
359
354
-opaque type SuspendedReason = 0 | 1 | 2 | 3 | 4 | 5 | 6 | 7 | 8 | 9;
360
+export opaque type SuspendedReason = 0 | 1 | 2 | 3 | 4 | 5 | 6 | 7 | 8 | 9;
361
const NotSuspended: SuspendedReason = 0;
362
const SuspendedOnError: SuspendedReason = 1;
363
const SuspendedOnData: SuspendedReason = 2;
@@ -915,6 +921,24 @@ export function performWorkOnRoot(
921
throw new Error('Should not already be working.');
922
}
923
924
+ if (enableProfilerTimer && enableComponentPerformanceTrack) {
925
+ if (workInProgressRootRenderLanes !== NoLanes && workInProgress !== null) {
926
+ const yieldedFiber = workInProgress;
927
+ // We've returned from yielding to the event loop. Let's log the time it took.
928
+ const yieldEndTime = now();
929
+ switch (yieldReason) {
930
+ case SuspendedOnData:
931
+ logSuspendedYieldTime(yieldStartTime, yieldEndTime, yieldedFiber);
932
+ break;
933
+ case SuspendedOnAction:
934
+ logActionYieldTime(yieldStartTime, yieldEndTime, yieldedFiber);
935
+ break;
936
+ default:
937
+ logYieldTime(yieldStartTime, yieldEndTime);
938
+ }
939
+ }
940
+ }
941
+
942
// We disable time-slicing in some cases: if the work has been CPU-bound
943
// for too long ("expired" work, to prevent starvation), or we're in
944
// sync-updates-by-default mode.
@@ -956,6 +980,12 @@ export function performWorkOnRoot(
980
const didAttemptEntireTree = false;
981
markRootSuspended(root, lanes, NoLane, didAttemptEntireTree);
982
}
983
+ if (enableProfilerTimer && enableComponentPerformanceTrack) {
984
+ // We're about to yield. Let's keep track of how long we yield to the event loop.
985
+ // We also stash the suspended reason at the time we yielded since it might have
986
+ // changed when we resume such as when it gets pinged.
987
+ startYieldTimer(workInProgressSuspendedReason);
988
+ }
989
break;
990
} else {
991
let renderEndTime = 0;
packages/react-reconciler/src/ReactProfilerTimer.js
+13
@@ -9,6 +9,8 @@
9
10
import type {Fiber} from './ReactInternalTypes';
11
12
+import type {SuspendedReason} from './ReactFiberWorkLoop';
13
+
14
import type {Lane, Lanes} from './ReactFiberLane';
15
import {
16
isTransitionLane,
@@ -58,6 +60,17 @@ export let transitionEventType: null | string = null; // Event type of the first
60
export let transitionEventIsRepeat: boolean = false;
61
export let transitionSuspendedTime: number = -1.1;
62
63
+export let yieldReason: SuspendedReason = (0: any);
64
+export let yieldStartTime: number = -1.1; // The time when we yielded to the event loop
65
+
66
+export function startYieldTimer(reason: SuspendedReason) {
67
+ if (!enableProfilerTimer || !enableComponentPerformanceTrack) {
68
+ return;
69
+ }
70
+ yieldStartTime = now();
71
+ yieldReason = reason;
72
+}
73
+
74
export function startUpdateTimerByLane(lane: Lane): void {
75
if (!enableProfilerTimer || !enableComponentPerformanceTrack) {
76
return;