@samitouri / QOS-React / commits / 4e9540e3c2

[Fiber] Log the Render/Commit phases and the gaps in between (#31016)

A slight behavior change here too is that I now mark the start of the commit phase before the BeforeMutationEffect phase. This affects `<Profiler>` too. The named sequences are as follows: Render -> Suspended or Throttled -> Commit -> Waiting for Paint -> Remaining Effects The Suspended phase is only logged if we delay the Commit due to CSS / images. The Throttled phase is only logged if we delay the commit due to the Suspense throttling timer. <img width="1246" alt="Screenshot 2024-09-20 at 9 14 23 PM" src="https://github.com/user-attachments/assets/8d01f444-bb85-472b-9b42-6157d92c81b4"> I don't yet log render phases that don't complete. I think I also need to special case renders that or don't commit after being suspended.

Sebastian Markbåge committed Sep 23, 2024 at 14:09 UTC 4e9540e3c2a8f9ae56318b967939c99b3a815190
6 files changed +184 -44
packages/react-reconciler/src/ReactFiberCommitEffects.js
+11 -11
@@ -899,7 +899,7 @@ function safelyCallDestroy(
899 function commitProfiler(
900 finishedWork: Fiber,
901 current: Fiber | null,
902 - commitTime: number,
902 + commitStartTime: number,
903 effectDuration: number,
904 ) {
905 const {id, onCommit, onRender} = finishedWork.memoizedProps;
@@ -918,7 +918,7 @@ function commitProfiler(
918 finishedWork.actualDuration,
919 finishedWork.treeBaseDuration,
920 finishedWork.actualStartTime,
921 - commitTime,
921 + commitStartTime,
922 );
923 }
924
@@ -928,7 +928,7 @@ function commitProfiler(
928 finishedWork.memoizedProps.id,
929 phase,
930 effectDuration,
931 - commitTime,
931 + commitStartTime,
932 );
933 }
934 }
@@ -937,7 +937,7 @@ function commitProfiler(
937 export function commitProfilerUpdate(
938 finishedWork: Fiber,
939 current: Fiber | null,
940 - commitTime: number,
940 + commitStartTime: number,
941 effectDuration: number,
942 ) {
943 if (enableProfilerTimer) {
@@ -948,11 +948,11 @@ export function commitProfilerUpdate(
948 commitProfiler,
949 finishedWork,
950 current,
951 - commitTime,
951 + commitStartTime,
952 effectDuration,
953 );
954 } else {
955 - commitProfiler(finishedWork, current, commitTime, effectDuration);
955 + commitProfiler(finishedWork, current, commitStartTime, effectDuration);
956 }
957 } catch (error) {
958 captureCommitPhaseError(finishedWork, finishedWork.return, error);
@@ -963,7 +963,7 @@ export function commitProfilerUpdate(
963 function commitProfilerPostCommitImpl(
964 finishedWork: Fiber,
965 current: Fiber | null,
966 - commitTime: number,
966 + commitStartTime: number,
967 passiveEffectDuration: number,
968 ): void {
969 const {id, onPostCommit} = finishedWork.memoizedProps;
@@ -976,14 +976,14 @@ function commitProfilerPostCommitImpl(
976 }
977
978 if (typeof onPostCommit === 'function') {
979 - onPostCommit(id, phase, passiveEffectDuration, commitTime);
979 + onPostCommit(id, phase, passiveEffectDuration, commitStartTime);
980 }
981 }
982
983 export function commitProfilerPostCommit(
984 finishedWork: Fiber,
985 current: Fiber | null,
986 - commitTime: number,
986 + commitStartTime: number,
987 passiveEffectDuration: number,
988 ) {
989 try {
@@ -993,14 +993,14 @@ export function commitProfilerPostCommit(
993 commitProfilerPostCommitImpl,
994 finishedWork,
995 current,
996 - commitTime,
996 + commitStartTime,
997 passiveEffectDuration,
998 );
999 } else {
1000 commitProfilerPostCommitImpl(
1001 finishedWork,
1002 current,
1003 - commitTime,
1003 + commitStartTime,
1004 passiveEffectDuration,
1005 );
1006 }
packages/react-reconciler/src/ReactFiberCommitWork.js
+6 -6
@@ -99,8 +99,7 @@ import {
99 Cloned,
100 } from './ReactFiberFlags';
101 import {
102 - commitTime,
103 - completeTime,
102 + commitStartTime,
103 pushNestedEffectDurations,
104 popNestedEffectDurations,
105 bubbleNestedEffectDurations,
@@ -505,7 +504,7 @@ function commitLayoutEffectOnFiber(
504 commitProfilerUpdate(
505 finishedWork,
506 current,
508 - commitTime,
507 + commitStartTime,
508 profilerInstance.effectDuration,
509 );
510 } else {
@@ -2345,7 +2344,7 @@ export function reappearLayoutEffects(
2344 commitProfilerUpdate(
2345 finishedWork,
2346 current,
2348 - commitTime,
2347 + commitStartTime,
2348 profilerInstance.effectDuration,
2349 );
2350 } else {
@@ -2568,6 +2567,7 @@ export function commitPassiveMountEffects(
2567 finishedWork: Fiber,
2568 committedLanes: Lanes,
2569 committedTransitions: Array<Transition> | null,
2570 + renderEndTime: number, // Profiling-only
2571 ): void {
2572 resetComponentEffectTimers();
2573
@@ -2576,7 +2576,7 @@ export function commitPassiveMountEffects(
2576 finishedWork,
2577 committedLanes,
2578 committedTransitions,
2579 - enableProfilerTimer && enableComponentPerformanceTrack ? completeTime : 0,
2579 + enableProfilerTimer && enableComponentPerformanceTrack ? renderEndTime : 0,
2580 );
2581 }
2582
@@ -2763,7 +2763,7 @@ function commitPassiveMountOnFiber(
2763 finishedWork.alternate,
2764 // This value will still reflect the previous commit phase.
2765 // It does not get reset until the start of the next commit phase.
2766 - commitTime,
2766 + commitStartTime,
2767 profilerInstance.passiveEffectDuration,
2768 );
2769 } else {
packages/react-reconciler/src/ReactFiberPerformanceTrack.js
+65
@@ -164,3 +164,68 @@ export function logTransitionStart(
164 }
165 }
166 }
167 +
168 +export function logRenderPhase(startTime: number, endTime: number): void {
169 + if (supportsUserTiming) {
170 + reusableComponentDevToolDetails.color = 'primary-dark';
171 + reusableComponentOptions.start = startTime;
172 + reusableComponentOptions.end = endTime;
173 + performance.measure('Render', reusableComponentOptions);
174 + }
175 +}
176 +
177 +export function logSuspenseThrottlePhase(
178 + startTime: number,
179 + endTime: number,
180 +): void {
181 + // This was inside a throttled Suspense boundary commit.
182 + if (supportsUserTiming) {
183 + reusableComponentDevToolDetails.color = 'secondary-light';
184 + reusableComponentOptions.start = startTime;
185 + reusableComponentOptions.end = endTime;
186 + performance.measure('Throttled', reusableComponentOptions);
187 + }
188 +}
189 +
190 +export function logSuspendedCommitPhase(
191 + startTime: number,
192 + endTime: number,
193 +): void {
194 + // This means the commit was suspended on CSS or images.
195 + if (supportsUserTiming) {
196 + reusableComponentDevToolDetails.color = 'secondary-light';
197 + reusableComponentOptions.start = startTime;
198 + reusableComponentOptions.end = endTime;
199 + performance.measure('Suspended', reusableComponentOptions);
200 + }
201 +}
202 +
203 +export function logCommitPhase(startTime: number, endTime: number): void {
204 + if (supportsUserTiming) {
205 + reusableComponentDevToolDetails.color = 'secondary-dark';
206 + reusableComponentOptions.start = startTime;
207 + reusableComponentOptions.end = endTime;
208 + performance.measure('Commit', reusableComponentOptions);
209 + }
210 +}
211 +
212 +export function logPaintYieldPhase(startTime: number, endTime: number): void {
213 + if (supportsUserTiming) {
214 + reusableComponentDevToolDetails.color = 'secondary-light';
215 + reusableComponentOptions.start = startTime;
216 + reusableComponentOptions.end = endTime;
217 + performance.measure('Waiting for Paint', reusableComponentOptions);
218 + }
219 +}
220 +
221 +export function logPassiveCommitPhase(
222 + startTime: number,
223 + endTime: number,
224 +): void {
225 + if (supportsUserTiming) {
226 + reusableComponentDevToolDetails.color = 'secondary-dark';
227 + reusableComponentOptions.start = startTime;
228 + reusableComponentOptions.end = endTime;
229 + performance.measure('Remaining Effects', reusableComponentOptions);
230 + }
231 +}
packages/react-reconciler/src/ReactFiberWorkLoop.js
+94 -21
@@ -71,6 +71,12 @@ import {
71 import {
72 logBlockingStart,
73 logTransitionStart,
74 + logRenderPhase,
75 + logSuspenseThrottlePhase,
76 + logSuspendedCommitPhase,
77 + logCommitPhase,
78 + logPaintYieldPhase,
79 + logPassiveCommitPhase,
80 } from './ReactFiberPerformanceTrack';
81
82 import {
@@ -239,9 +245,11 @@ import {
245 clampTransitionTimers,
246 markNestedUpdateScheduled,
247 renderStartTime,
248 + commitStartTime,
249 + commitEndTime,
250 recordRenderTime,
243 - recordCompleteTime,
251 recordCommitTime,
252 + recordCommitEndTime,
253 resetNestedUpdateFlag,
254 startProfilerTimer,
255 stopProfilerTimerIfRunningAndRecordDuration,
@@ -601,6 +609,7 @@ let rootDoesHavePassiveEffects: boolean = false;
609 let rootWithPendingPassiveEffects: FiberRoot | null = null;
610 let pendingPassiveEffectsLanes: Lanes = NoLanes;
611 let pendingPassiveEffectsRemainingLanes: Lanes = NoLanes;
612 +let pendingPassiveEffectsRenderEndTime: number = -0; // Profiling-only
613 let pendingPassiveTransitions: Array<Transition> | null = null;
614
615 // Use these to prevent an infinite loop of nested updates
@@ -1119,10 +1128,11 @@ function finishConcurrentRender(
1128 finishedWork: Fiber,
1129 lanes: Lanes,
1130 ) {
1131 + let renderEndTime = 0;
1132 if (enableProfilerTimer && enableComponentPerformanceTrack) {
1133 // Track when we finished the last unit of work, before we actually commit it.
1134 // The commit can be suspended/blocked until we commit it.
1125 - recordCompleteTime();
1135 + renderEndTime = now();
1136 }
1137
1138 // TODO: The fact that most of these branches are identical suggests that some
@@ -1182,6 +1192,9 @@ function finishConcurrentRender(
1192 workInProgressDeferredLane,
1193 workInProgressRootInterleavedUpdatedLanes,
1194 workInProgressSuspendedRetryLanes,
1195 + IMMEDIATE_COMMIT,
1196 + renderStartTime,
1197 + renderEndTime,
1198 );
1199 } else {
1200 if (
@@ -1227,6 +1240,9 @@ function finishConcurrentRender(
1240 workInProgressRootInterleavedUpdatedLanes,
1241 workInProgressSuspendedRetryLanes,
1242 workInProgressRootDidSkipSuspendedSiblings,
1243 + THROTTLED_COMMIT,
1244 + renderStartTime,
1245 + renderEndTime,
1246 ),
1247 msUntilTimeout,
1248 );
@@ -1244,6 +1260,9 @@ function finishConcurrentRender(
1260 workInProgressRootInterleavedUpdatedLanes,
1261 workInProgressSuspendedRetryLanes,
1262 workInProgressRootDidSkipSuspendedSiblings,
1263 + IMMEDIATE_COMMIT,
1264 + renderStartTime,
1265 + renderEndTime,
1266 );
1267 }
1268 }
@@ -1259,6 +1278,9 @@ function commitRootWhenReady(
1278 updatedLanes: Lanes,
1279 suspendedRetryLanes: Lanes,
1280 didSkipSuspendedSiblings: boolean,
1281 + suspendedCommitReason: SuspendedCommitReason, // Profiling-only
1282 + completedRenderStartTime: number, // Profiling-only
1283 + completedRenderEndTime: number, // Profiling-only
1284 ) {
1285 // TODO: Combine retry throttling with Suspensey commits. Right now they run
1286 // one after the other.
@@ -1299,6 +1321,7 @@ function commitRootWhenReady(
1321 spawnedLane,
1322 updatedLanes,
1323 suspendedRetryLanes,
1324 + SUSPENDED_COMMIT,
1325 ),
1326 );
1327 markRootSuspended(root, lanes, spawnedLane, didSkipSuspendedSiblings);
@@ -1315,6 +1338,9 @@ function commitRootWhenReady(
1338 spawnedLane,
1339 updatedLanes,
1340 suspendedRetryLanes,
1341 + suspendedCommitReason,
1342 + completedRenderStartTime,
1343 + completedRenderEndTime,
1344 );
1345 }
1346
@@ -1506,8 +1532,9 @@ export function performSyncWorkOnRoot(root: FiberRoot, lanes: Lanes): null {
1532 return null;
1533 }
1534
1535 + let renderEndTime = 0;
1536 if (enableProfilerTimer && enableComponentPerformanceTrack) {
1510 - recordCompleteTime();
1537 + renderEndTime = now();
1538 }
1539
1540 // We now have a consistent tree. Because this is a sync render, we
@@ -1523,6 +1550,9 @@ export function performSyncWorkOnRoot(root: FiberRoot, lanes: Lanes): null {
1550 workInProgressDeferredLane,
1551 workInProgressRootInterleavedUpdatedLanes,
1552 workInProgressSuspendedRetryLanes,
1553 + IMMEDIATE_COMMIT,
1554 + renderStartTime,
1555 + renderEndTime,
1556 );
1557
1558 // Before exiting, make sure there's a callback scheduled for the next
@@ -3016,6 +3046,11 @@ function unwindUnitOfWork(unitOfWork: Fiber, skipSiblings: boolean): void {
3046 workInProgress = null;
3047 }
3048
3049 +type SuspendedCommitReason = 0 | 1 | 2;
3050 +const IMMEDIATE_COMMIT = 0;
3051 +const SUSPENDED_COMMIT = 1;
3052 +const THROTTLED_COMMIT = 2;
3053 +
3054 function commitRoot(
3055 root: FiberRoot,
3056 recoverableErrors: null | Array<CapturedValue<mixed>>,
@@ -3024,6 +3059,9 @@ function commitRoot(
3059 spawnedLane: Lane,
3060 updatedLanes: Lanes,
3061 suspendedRetryLanes: Lanes,
3062 + suspendedCommitReason: SuspendedCommitReason, // Profiling-only
3063 + completedRenderStartTime: number, // Profiling-only
3064 + completedRenderEndTime: number, // Profiling-only
3065 ) {
3066 // TODO: This no longer makes any sense. We already wrap the mutation and
3067 // layout phases. Should be able to remove.
@@ -3041,6 +3079,9 @@ function commitRoot(
3079 spawnedLane,
3080 updatedLanes,
3081 suspendedRetryLanes,
3082 + suspendedCommitReason,
3083 + completedRenderStartTime,
3084 + completedRenderEndTime,
3085 );
3086 } finally {
3087 ReactSharedInternals.T = prevTransition;
@@ -3059,6 +3100,9 @@ function commitRootImpl(
3100 spawnedLane: Lane,
3101 updatedLanes: Lanes,
3102 suspendedRetryLanes: Lanes,
3103 + suspendedCommitReason: SuspendedCommitReason, // Profiling-only
3104 + completedRenderStartTime: number, // Profiling-only
3105 + completedRenderEndTime: number, // Profiling-only
3106 ) {
3107 do {
3108 // `flushPassiveEffects` will call `flushSyncUpdateQueue` at the end, which
@@ -3078,6 +3122,12 @@ function commitRootImpl(
3122 const finishedWork = root.finishedWork;
3123 const lanes = root.finishedLanes;
3124
3125 + if (enableProfilerTimer && enableComponentPerformanceTrack) {
3126 + // Log the previous render phase once we commit. I.e. we weren't interrupted.
3127 + setCurrentTrackFromLanes(lanes);
3128 + logRenderPhase(completedRenderStartTime, completedRenderEndTime);
3129 + }
3130 +
3131 if (__DEV__) {
3132 if (enableDebugTracing) {
3133 logCommitStarted(lanes);
@@ -3174,6 +3224,7 @@ function commitRootImpl(
3224 if (!rootDoesHavePassiveEffects) {
3225 rootDoesHavePassiveEffects = true;
3226 pendingPassiveEffectsRemainingLanes = remainingLanes;
3227 + pendingPassiveEffectsRenderEndTime = completedRenderEndTime;
3228 // workInProgressTransitions might be overwritten, so we want
3229 // to store it in pendingPassiveTransitions until they get processed
3230 // We need to pass this through as an argument to commitRoot
@@ -3182,7 +3233,7 @@ function commitRootImpl(
3233 // with setTimeout
3234 pendingPassiveTransitions = transitions;
3235 scheduleCallback(NormalSchedulerPriority, () => {
3185 - flushPassiveEffects();
3236 + flushPassiveEffects(true);
3237 // This render triggered passive effects: release the root cache pool
3238 // *after* passive effects fire to avoid freeing a cache pool that may
3239 // be referenced by a node in the tree (HostRoot, Cache boundary etc)
@@ -3191,6 +3242,19 @@ function commitRootImpl(
3242 }
3243 }
3244
3245 + if (enableProfilerTimer) {
3246 + // Mark the current commit time to be shared by all Profilers in this
3247 + // batch. This enables them to be grouped later.
3248 + recordCommitTime();
3249 + if (enableComponentPerformanceTrack) {
3250 + if (suspendedCommitReason === SUSPENDED_COMMIT) {
3251 + logSuspendedCommitPhase(completedRenderEndTime, commitStartTime);
3252 + } else if (suspendedCommitReason === THROTTLED_COMMIT) {
3253 + logSuspenseThrottlePhase(completedRenderEndTime, commitStartTime);
3254 + }
3255 + }
3256 + }
3257 +
3258 // Check if there are any effects in the whole tree.
3259 // TODO: This is left over from the effect list implementation, where we had
3260 // to check for the existence of `firstEffect` to satisfy Flow. I think the
@@ -3226,12 +3290,6 @@ function commitRootImpl(
3290 finishedWork,
3291 );
3292
3229 - if (enableProfilerTimer) {
3230 - // Mark the current commit time to be shared by all Profilers in this
3231 - // batch. This enables them to be grouped later.
3232 - recordCommitTime();
3233 - }
3234 -
3293 // The next phase is the mutation phase, where we mutate the host tree.
3294 commitMutationEffects(root, finishedWork, lanes);
3295
@@ -3282,12 +3340,11 @@ function commitRootImpl(
3340 } else {
3341 // No effects.
3342 root.current = finishedWork;
3285 - // Measure these anyway so the flamegraph explicitly shows that there were
3286 - // no effects.
3287 - // TODO: Maybe there's a better way to report this.
3288 - if (enableProfilerTimer) {
3289 - recordCommitTime();
3290 - }
3343 + }
3344 +
3345 + if (enableProfilerTimer && enableComponentPerformanceTrack) {
3346 + recordCommitEndTime();
3347 + logCommitPhase(commitStartTime, commitEndTime);
3348 }
3349
3350 const rootDidHavePassiveEffects = rootDoesHavePassiveEffects;
@@ -3504,7 +3561,7 @@ function releaseRootPooledCache(root: FiberRoot, remainingLanes: Lanes) {
3561 }
3562 }
3563
3507 -export function flushPassiveEffects(): boolean {
3564 +export function flushPassiveEffects(wasDelayedCommit?: boolean): boolean {
3565 // Returns whether passive effects were flushed.
3566 // TODO: Combine this check with the one in flushPassiveEFfectsImpl. We should
3567 // probably just combine the two functions. I believe they were only separate
@@ -3529,7 +3586,7 @@ export function flushPassiveEffects(): boolean {
3586 try {
3587 setCurrentUpdatePriority(priority);
3588 ReactSharedInternals.T = null;
3532 - return flushPassiveEffectsImpl();
3589 + return flushPassiveEffectsImpl(wasDelayedCommit);
3590 } finally {
3591 setCurrentUpdatePriority(previousPriority);
3592 ReactSharedInternals.T = prevTransition;
@@ -3543,7 +3600,7 @@ export function flushPassiveEffects(): boolean {
3600 return false;
3601 }
3602
3546 -function flushPassiveEffectsImpl() {
3603 +function flushPassiveEffectsImpl(wasDelayedCommit: void | boolean) {
3604 if (rootWithPendingPassiveEffects === null) {
3605 return false;
3606 }
@@ -3579,6 +3636,12 @@ function flushPassiveEffectsImpl() {
3636 }
3637 }
3638
3639 + let passiveEffectStartTime = 0;
3640 + if (enableProfilerTimer && enableComponentPerformanceTrack) {
3641 + passiveEffectStartTime = now();
3642 + logPaintYieldPhase(commitEndTime, passiveEffectStartTime);
3643 + }
3644 +
3645 if (enableSchedulingProfiler) {
3646 markPassiveEffectsStarted(lanes);
3647 }
@@ -3587,7 +3650,13 @@ function flushPassiveEffectsImpl() {
3650 executionContext |= CommitContext;
3651
3652 commitPassiveUnmountEffects(root.current);
3590 - commitPassiveMountEffects(root, root.current, lanes, transitions);
3653 + commitPassiveMountEffects(
3654 + root,
3655 + root.current,
3656 + lanes,
3657 + transitions,
3658 + pendingPassiveEffectsRenderEndTime,
3659 + );
3660
3661 if (__DEV__) {
3662 if (enableDebugTracing) {
@@ -3606,7 +3675,11 @@ function flushPassiveEffectsImpl() {
3675 executionContext = prevExecutionContext;
3676
3677 if (enableProfilerTimer && enableComponentPerformanceTrack) {
3609 - finalizeRender(lanes, now());
3678 + const passiveEffectsEndTime = now();
3679 + if (wasDelayedCommit) {
3680 + logPassiveCommitPhase(passiveEffectStartTime, passiveEffectsEndTime);
3681 + }
3682 + finalizeRender(lanes, passiveEffectsEndTime);
3683 }
3684
3685 flushSyncWorkOnAllRoots();
packages/react-reconciler/src/ReactProfilerTimer.js
+6 -6
@@ -28,8 +28,8 @@ import * as Scheduler from 'scheduler';
28 const {unstable_now: now} = Scheduler;
29
30 export let renderStartTime: number = -0;
31 -export let completeTime: number = -0;
32 -export let commitTime: number = -0;
31 +export let commitStartTime: number = -0;
32 +export let commitEndTime: number = -0;
33 export let profilerStartTime: number = -1.1;
34 export let profilerEffectDuration: number = -0;
35 export let componentEffectDuration: number = -0;
@@ -255,18 +255,18 @@ export function recordRenderTime(): void {
255 renderStartTime = now();
256 }
257
258 -export function recordCompleteTime(): void {
258 +export function recordCommitTime(): void {
259 if (!enableProfilerTimer) {
260 return;
261 }
262 - completeTime = now();
262 + commitStartTime = now();
263 }
264
265 -export function recordCommitTime(): void {
265 +export function recordCommitEndTime(): void {
266 if (!enableProfilerTimer) {
267 return;
268 }
269 - commitTime = now();
269 + commitEndTime = now();
270 }
271
272 export function startProfilerTimer(fiber: Fiber): void {
packages/react/src/__tests__/ReactProfiler-test.internal.js
+2
@@ -181,6 +181,7 @@ describe(`onRender`, () => {
181 'read current time',
182 'read current time',
183 'read current time',
184 + 'read current time',
185 ]);
186 } else {
187 assertLog([
@@ -218,6 +219,7 @@ describe(`onRender`, () => {
219 'read current time',
220 'read current time',
221 'read current time',
222 + 'read current time',
223 ]);
224 } else {
225 assertLog([