[Fiber] Log Component Renders to Custom Performance Track (#30967)
Stacked on #30960 and #30966. Behind the enableComponentPerformanceTrack flag. This is the first step of performance logging. This logs the start and end time of a component render in the passive effect phase. We use the data we're already tracking on components when the Profiler component or DevTools is active in the Profiling or Dev builds. By backdating this after committing we avoid adding more overhead in the hot path. By only logging things that actually committed, we avoid the costly unwinding of an interrupted render which was hard to maintain in earlier versions. We already have the start time but we don't have the end time. That's because `actualStartTime + actualDuration` isn't enough since `actualDuration` counts the actual CPU time excluding yields and suspending in the render. Instead, we infer the end time to be the start time of the next sibling or the complete time of the whole root if there are no more siblings. We need to pass this down the passive effect tree. This will mean that any overhead and yields are attributed to this component's span. In a follow up, we'll need to start logging these yields to make it clear that this is not part of the component's self-time. In follow ups, I'll do the same for commit phases. We'll also need to log more information about the phases in the top track. We'll also need to filter out more components from the trees that we don't need to highlight like the internal Offscreen components. It also needs polish on colors etc. Currently, I place the components into separate tracks depending on which lane currently committed. That way you can see what was blocking Transitions or Suspense etc. One problem that I've hit with the new performance.measure extensions is that these tracks show up in the order they're used which is not the order of priority that we use. Even when you add fake markers they have to actually be within the performance run since otherwise the calls are noops so it's not enough to do that once. However, I think this visualization is actually not good because these trees end up so large that you can't see any other lanes once you expand one. Therefore, I think in a follow up I'll actually instead switch to a model where Components is a single track regardless of lane since we don't currently have overlap anyway. Then the description about what is actually rendering can be separate lanes. <img width="1512" alt="Screenshot 2024-09-15 at 10 55 55 PM" src="https://github.com/user-attachments/assets/5ca3fa74-97ce-40c7-97f7-80c1dd7d6470"> <img width="1512" alt="Screenshot 2024-09-15 at 10 56 27 PM" src="https://github.com/user-attachments/assets/557ad65b-4190-465f-843c-0bc6cbb9326d">
Sebastian Markbåge committed
Sep 16, 2024 at 11:45 UTC
f2df5694f2be141954f22618fd3ad035203241a3
7 files changed
+285
-49
packages/react-reconciler/src/ReactFiberCommitWork.js
+66
-8
@@ -53,6 +53,7 @@ import {
53
enableUseEffectEventHook,
54
enableLegacyHidden,
55
disableLegacyMode,
56
+ enableComponentPerformanceTrack,
57
} from 'shared/ReactFeatureFlags';
58
import {
59
FunctionComponent,
@@ -102,7 +103,9 @@ import {
103
getCommitTime,
104
recordLayoutEffectDuration,
105
startLayoutEffectTimer,
106
+ getCompleteTime,
107
} from './ReactProfilerTimer';
108
+import {logComponentRender} from './ReactFiberPerformanceTrack';
109
import {ConcurrentMode, NoMode, ProfileMode} from './ReactTypeOfMode';
110
import {deferHiddenCallbacks} from './ReactFiberClassUpdateQueue';
111
import {
@@ -2648,6 +2651,9 @@ export function commitPassiveMountEffects(
2651
finishedWork,
2652
committedLanes,
2653
committedTransitions,
2654
+ enableProfilerTimer && enableComponentPerformanceTrack
2655
+ ? getCompleteTime()
2656
+ : 0,
2657
);
2658
}
2659
@@ -2656,17 +2662,41 @@ function recursivelyTraversePassiveMountEffects(
2662
parentFiber: Fiber,
2663
committedLanes: Lanes,
2664
committedTransitions: Array<Transition> | null,
2665
+ endTime: number, // Profiling-only. The start time of the next Fiber or root completion.
2666
) {
2660
- if (parentFiber.subtreeFlags & PassiveMask) {
2667
+ if (
2668
+ parentFiber.subtreeFlags & PassiveMask ||
2669
+ // If this subtree rendered with profiling this commit, we need to visit it to log it.
2670
+ (enableProfilerTimer &&
2671
+ enableComponentPerformanceTrack &&
2672
+ parentFiber.actualDuration !== 0 &&
2673
+ (parentFiber.alternate === null ||
2674
+ parentFiber.alternate.child !== parentFiber.child))
2675
+ ) {
2676
let child = parentFiber.child;
2677
while (child !== null) {
2663
- commitPassiveMountOnFiber(
2664
- root,
2665
- child,
2666
- committedLanes,
2667
- committedTransitions,
2668
- );
2669
- child = child.sibling;
2678
+ if (enableProfilerTimer && enableComponentPerformanceTrack) {
2679
+ const nextSibling = child.sibling;
2680
+ commitPassiveMountOnFiber(
2681
+ root,
2682
+ child,
2683
+ committedLanes,
2684
+ committedTransitions,
2685
+ nextSibling !== null
2686
+ ? ((nextSibling.actualStartTime: any): number)
2687
+ : endTime,
2688
+ );
2689
+ child = nextSibling;
2690
+ } else {
2691
+ commitPassiveMountOnFiber(
2692
+ root,
2693
+ child,
2694
+ committedLanes,
2695
+ committedTransitions,
2696
+ 0,
2697
+ );
2698
+ child = child.sibling;
2699
+ }
2700
}
2701
}
2702
}
@@ -2676,7 +2706,25 @@ function commitPassiveMountOnFiber(
2706
finishedWork: Fiber,
2707
committedLanes: Lanes,
2708
committedTransitions: Array<Transition> | null,
2709
+ endTime: number, // Profiling-only. The start time of the next Fiber or root completion.
2710
): void {
2711
+ // If this component rendered in Profiling mode (DEV or in Profiler component) then log its
2712
+ // render time. We do this after the fact in the passive effect to avoid the overhead of this
2713
+ // getting in the way of the render characteristics and avoid the overhead of unwinding
2714
+ // uncommitted renders.
2715
+ if (
2716
+ enableProfilerTimer &&
2717
+ enableComponentPerformanceTrack &&
2718
+ (finishedWork.mode & ProfileMode) !== NoMode &&
2719
+ ((finishedWork.actualStartTime: any): number) > 0
2720
+ ) {
2721
+ logComponentRender(
2722
+ finishedWork,
2723
+ ((finishedWork.actualStartTime: any): number),
2724
+ endTime,
2725
+ );
2726
+ }
2727
+
2728
// When updating this function, also update reconnectPassiveEffects, which does
2729
// most of the same things when an offscreen tree goes from hidden -> visible,
2730
// or when toggling effects inside a hidden tree.
@@ -2690,6 +2738,7 @@ function commitPassiveMountOnFiber(
2738
finishedWork,
2739
committedLanes,
2740
committedTransitions,
2741
+ endTime,
2742
);
2743
if (flags & Passive) {
2744
commitHookPassiveMountEffects(
@@ -2705,6 +2754,7 @@ function commitPassiveMountOnFiber(
2754
finishedWork,
2755
committedLanes,
2756
committedTransitions,
2757
+ endTime,
2758
);
2759
if (flags & Passive) {
2760
if (enableCache) {
@@ -2762,6 +2812,7 @@ function commitPassiveMountOnFiber(
2812
finishedWork,
2813
committedLanes,
2814
committedTransitions,
2815
+ endTime,
2816
);
2817
2818
// Only Profilers with work in their subtree will have a Passive effect scheduled.
@@ -2809,6 +2860,7 @@ function commitPassiveMountOnFiber(
2860
finishedWork,
2861
committedLanes,
2862
committedTransitions,
2863
+ endTime,
2864
);
2865
2866
if (flags & Passive) {
@@ -2834,6 +2886,7 @@ function commitPassiveMountOnFiber(
2886
finishedWork,
2887
committedLanes,
2888
committedTransitions,
2889
+ endTime,
2890
);
2891
} else {
2892
if (disableLegacyMode || finishedWork.mode & ConcurrentMode) {
@@ -2858,6 +2911,7 @@ function commitPassiveMountOnFiber(
2911
finishedWork,
2912
committedLanes,
2913
committedTransitions,
2914
+ endTime,
2915
);
2916
}
2917
}
@@ -2870,6 +2924,7 @@ function commitPassiveMountOnFiber(
2924
finishedWork,
2925
committedLanes,
2926
committedTransitions,
2927
+ endTime,
2928
);
2929
} else {
2930
// The effects are currently disconnected. Reconnect them, while also
@@ -2901,6 +2956,7 @@ function commitPassiveMountOnFiber(
2956
finishedWork,
2957
committedLanes,
2958
committedTransitions,
2959
+ endTime,
2960
);
2961
if (flags & Passive) {
2962
// TODO: Pass `current` as argument to this function
@@ -2916,6 +2972,7 @@ function commitPassiveMountOnFiber(
2972
finishedWork,
2973
committedLanes,
2974
committedTransitions,
2975
+ endTime,
2976
);
2977
if (flags & Passive) {
2978
commitTracingMarkerPassiveMountEffect(finishedWork);
@@ -2930,6 +2987,7 @@ function commitPassiveMountOnFiber(
2987
finishedWork,
2988
committedLanes,
2989
committedTransitions,
2990
+ endTime,
2991
);
2992
break;
2993
}
packages/react-reconciler/src/ReactFiberLane.js
+32
@@ -1143,3 +1143,35 @@ export function clearTransitionsForLanes(root: FiberRoot, lanes: Lane | Lanes) {
1143
lanes &= ~lane;
1144
}
1145
}
1146
+
1147
+// Used to name the Performance Track
1148
+export function getGroupNameOfHighestPriorityLane(lanes: Lanes): string {
1149
+ if (
1150
+ lanes &
1151
+ (SyncHydrationLane |
1152
+ SyncLane |
1153
+ InputContinuousHydrationLane |
1154
+ InputContinuousLane |
1155
+ DefaultHydrationLane |
1156
+ DefaultLane)
1157
+ ) {
1158
+ return 'Blocking';
1159
+ }
1160
+ if (lanes & (TransitionHydrationLane | TransitionLanes)) {
1161
+ return 'Transition';
1162
+ }
1163
+ if (lanes & RetryLanes) {
1164
+ return 'Suspense';
1165
+ }
1166
+ if (
1167
+ lanes &
1168
+ (SelectiveHydrationLane |
1169
+ IdleHydrationLane |
1170
+ IdleLane |
1171
+ OffscreenLane |
1172
+ DeferredLane)
1173
+ ) {
1174
+ return 'Idle';
1175
+ }
1176
+ return 'Other';
1177
+}
packages/react-reconciler/src/ReactFiberPerformanceTrack.js
new
+61
@@ -0,0 +1,61 @@
1
+/**
2
+ * Copyright (c) Meta Platforms, Inc. and affiliates.
3
+ *
4
+ * This source code is licensed under the MIT license found in the
5
+ * LICENSE file in the root directory of this source tree.
6
+ *
7
+ * @flow
8
+ */
9
+
10
+import type {Fiber} from './ReactInternalTypes';
11
+
12
+import getComponentNameFromFiber from './getComponentNameFromFiber';
13
+
14
+import {getGroupNameOfHighestPriorityLane} from './ReactFiberLane';
15
+
16
+import {enableProfilerTimer} from 'shared/ReactFeatureFlags';
17
+
18
+const supportsUserTiming =
19
+ enableProfilerTimer &&
20
+ typeof performance !== 'undefined' &&
21
+ // $FlowFixMe[method-unbinding]
22
+ typeof performance.measure === 'function';
23
+
24
+const TRACK_GROUP = 'Components ⚛';
25
+
26
+// Reused to avoid thrashing the GC.
27
+const reusableComponentDevToolDetails = {
28
+ dataType: 'track-entry',
29
+ color: 'primary',
30
+ track: 'Blocking', // Lane
31
+ trackGroup: TRACK_GROUP,
32
+};
33
+const reusableComponentOptions = {
34
+ start: -0,
35
+ end: -0,
36
+ detail: {
37
+ devtools: reusableComponentDevToolDetails,
38
+ },
39
+};
40
+
41
+export function setCurrentTrackFromLanes(lanes: number): void {
42
+ reusableComponentDevToolDetails.track =
43
+ getGroupNameOfHighestPriorityLane(lanes);
44
+}
45
+
46
+export function logComponentRender(
47
+ fiber: Fiber,
48
+ startTime: number,
49
+ endTime: number,
50
+): void {
51
+ const name = getComponentNameFromFiber(fiber);
52
+ if (name === null) {
53
+ // Skip
54
+ return;
55
+ }
56
+ if (supportsUserTiming) {
57
+ reusableComponentOptions.start = startTime;
58
+ reusableComponentOptions.end = endTime;
59
+ performance.measure(name, reusableComponentOptions);
60
+ }
61
+}
packages/react-reconciler/src/ReactFiberWorkLoop.js
+35
-25
@@ -44,6 +44,7 @@ import {
44
disableDefaultPropsExceptForClasses,
45
disableStringRefs,
46
enableSiblingPrerendering,
47
+ enableComponentPerformanceTrack,
48
} from 'shared/ReactFeatureFlags';
49
import ReactSharedInternals from 'shared/ReactSharedInternals';
50
import is from 'shared/objectIs';
@@ -221,6 +222,7 @@ import {
222
223
import {
224
markNestedUpdateScheduled,
225
+ recordCompleteTime,
226
recordCommitTime,
227
resetNestedUpdateFlag,
228
startProfilerTimer,
@@ -228,6 +230,7 @@ import {
230
stopProfilerTimerIfRunningAndRecordIncompleteDuration,
231
syncNestedUpdateFlag,
232
} from './ReactProfilerTimer';
233
+import {setCurrentTrackFromLanes} from './ReactFiberPerformanceTrack';
234
235
// DEV stuff
236
import getComponentNameFromFiber from 'react-reconciler/src/getComponentNameFromFiber';
@@ -1098,6 +1101,12 @@ function finishConcurrentRender(
1101
finishedWork: Fiber,
1102
lanes: Lanes,
1103
) {
1104
+ if (enableProfilerTimer && enableComponentPerformanceTrack) {
1105
+ // Track when we finished the last unit of work, before we actually commit it.
1106
+ // The commit can be suspended/blocked until we commit it.
1107
+ recordCompleteTime();
1108
+ }
1109
+
1110
// TODO: The fact that most of these branches are identical suggests that some
1111
// of the exit statuses are not best modeled as exit statuses and should be
1112
// tracked orthogonally.
@@ -1479,6 +1488,10 @@ export function performSyncWorkOnRoot(root: FiberRoot, lanes: Lanes): null {
1488
return null;
1489
}
1490
1491
+ if (enableProfilerTimer && enableComponentPerformanceTrack) {
1492
+ recordCompleteTime();
1493
+ }
1494
+
1495
// We now have a consistent tree. Because this is a sync render, we
1496
// will commit it even if something suspended.
1497
const finishedWork: Fiber = (root.current.alternate: any);
@@ -2824,35 +2837,22 @@ function completeUnitOfWork(unitOfWork: Fiber): void {
2837
const returnFiber = completedWork.return;
2838
2839
let next;
2827
- if (!enableProfilerTimer || (completedWork.mode & ProfileMode) === NoMode) {
2828
- if (__DEV__) {
2829
- next = runWithFiberInDEV(
2830
- completedWork,
2831
- completeWork,
2832
- current,
2833
- completedWork,
2834
- entangledRenderLanes,
2835
- );
2836
- } else {
2837
- next = completeWork(current, completedWork, entangledRenderLanes);
2838
- }
2840
+ startProfilerTimer(completedWork);
2841
+ if (__DEV__) {
2842
+ next = runWithFiberInDEV(
2843
+ completedWork,
2844
+ completeWork,
2845
+ current,
2846
+ completedWork,
2847
+ entangledRenderLanes,
2848
+ );
2849
} else {
2840
- startProfilerTimer(completedWork);
2841
- if (__DEV__) {
2842
- next = runWithFiberInDEV(
2843
- completedWork,
2844
- completeWork,
2845
- current,
2846
- completedWork,
2847
- entangledRenderLanes,
2848
- );
2849
- } else {
2850
- next = completeWork(current, completedWork, entangledRenderLanes);
2851
- }
2850
+ next = completeWork(current, completedWork, entangledRenderLanes);
2851
+ }
2852
+ if (enableProfilerTimer && (completedWork.mode & ProfileMode) !== NoMode) {
2853
// Update render duration assuming we didn't error.
2854
stopProfilerTimerIfRunningAndRecordIncompleteDuration(completedWork);
2855
}
2855
-
2856
if (next !== null) {
2857
// Completing this fiber spawned new work. Work on that next.
2858
workInProgress = next;
@@ -3104,6 +3104,10 @@ function commitRootImpl(
3104
// TODO: Delete all other places that schedule the passive effect callback
3105
// They're redundant.
3106
if (
3107
+ // If this subtree rendered with profiling this commit, we need to visit it to log it.
3108
+ (enableProfilerTimer &&
3109
+ enableComponentPerformanceTrack &&
3110
+ finishedWork.actualDuration !== 0) ||
3111
(finishedWork.subtreeFlags & PassiveMask) !== NoFlags ||
3112
(finishedWork.flags & PassiveMask) !== NoFlags
3113
) {
@@ -3494,6 +3498,12 @@ function flushPassiveEffectsImpl() {
3498
throw new Error('Cannot flush passive effects while already rendering.');
3499
}
3500
3501
+ if (enableProfilerTimer && enableComponentPerformanceTrack) {
3502
+ // We're about to log a lot of profiling for this commit.
3503
+ // We set this once so we don't have to recompute it for every log.
3504
+ setCurrentTrackFromLanes(lanes);
3505
+ }
3506
+
3507
if (__DEV__) {
3508
isFlushingPassiveEffects = true;
3509
didScheduleUpdateDuringPassiveEffects = false;
packages/react-reconciler/src/ReactProfilerTimer.js
+15
-1
@@ -35,6 +35,7 @@ export type ProfilerTimer = {
35
...
36
};
37
38
+let completeTime: number = 0;
39
let commitTime: number = 0;
40
let layoutEffectStartTime: number = -1;
41
let profilerStartTime: number = -1;
@@ -83,6 +84,17 @@ function syncNestedUpdateFlag(): void {
84
}
85
}
86
87
+function getCompleteTime(): number {
88
+ return completeTime;
89
+}
90
+
91
+function recordCompleteTime(): void {
92
+ if (!enableProfilerTimer) {
93
+ return;
94
+ }
95
+ completeTime = now();
96
+}
97
+
98
function getCommitTime(): number {
99
return commitTime;
100
}
@@ -233,10 +245,12 @@ function transferActualDuration(fiber: Fiber): void {
245
}
246
247
export {
248
+ getCompleteTime,
249
+ recordCompleteTime,
250
getCommitTime,
251
+ recordCommitTime,
252
isCurrentUpdateNested,
253
markNestedUpdateScheduled,
239
- recordCommitTime,
254
recordLayoutEffectDuration,
255
recordPassiveEffectDuration,
256
resetNestedUpdateFlag,
packages/react-reconciler/src/__tests__/ReactSuspenseList-test.js
+10
@@ -1,3 +1,13 @@
1
+/**
2
+ * Copyright (c) Meta Platforms, Inc. and affiliates.
3
+ *
4
+ * This source code is licensed under the MIT license found in the
5
+ * LICENSE file in the root directory of this source tree.
6
+ *
7
+ * @emails react-core
8
+ * @jest-environment node
9
+ */
10
+
11
let React;
12
let ReactNoop;
13
let Scheduler;
packages/react/src/__tests__/ReactProfiler-test.internal.js
+66
-15
@@ -164,22 +164,73 @@ describe(`onRender`, () => {
164
// TODO: unstable_now is called by more places than just the profiler.
165
// Rewrite this test so it's less fragile.
166
if (gate(flags => flags.enableDeferRootSchedulingToMicrotask)) {
167
- assertLog([
168
- 'read current time',
169
- 'read current time',
170
- 'read current time',
171
- 'read current time',
172
- ]);
167
+ if (gate(flags => flags.enableComponentPerformanceTrack)) {
168
+ assertLog([
169
+ 'read current time',
170
+ 'read current time',
171
+ 'read current time',
172
+ 'read current time',
173
+ 'read current time',
174
+ 'read current time',
175
+ 'read current time',
176
+ 'read current time',
177
+ 'read current time',
178
+ 'read current time',
179
+ 'read current time',
180
+ 'read current time',
181
+ ]);
182
+ } else {
183
+ assertLog([
184
+ 'read current time',
185
+ 'read current time',
186
+ 'read current time',
187
+ 'read current time',
188
+ 'read current time',
189
+ 'read current time',
190
+ 'read current time',
191
+ 'read current time',
192
+ 'read current time',
193
+ 'read current time',
194
+ 'read current time',
195
+ ]);
196
+ }
197
} else {
174
- assertLog([
175
- 'read current time',
176
- 'read current time',
177
- 'read current time',
178
- 'read current time',
179
- 'read current time',
180
- 'read current time',
181
- 'read current time',
182
- ]);
198
+ if (gate(flags => flags.enableComponentPerformanceTrack)) {
199
+ assertLog([
200
+ 'read current time',
201
+ 'read current time',
202
+ 'read current time',
203
+ 'read current time',
204
+ 'read current time',
205
+ 'read current time',
206
+ 'read current time',
207
+ 'read current time',
208
+ 'read current time',
209
+ 'read current time',
210
+ 'read current time',
211
+ 'read current time',
212
+ 'read current time',
213
+ 'read current time',
214
+ 'read current time',
215
+ ]);
216
+ } else {
217
+ assertLog([
218
+ 'read current time',
219
+ 'read current time',
220
+ 'read current time',
221
+ 'read current time',
222
+ 'read current time',
223
+ 'read current time',
224
+ 'read current time',
225
+ 'read current time',
226
+ 'read current time',
227
+ 'read current time',
228
+ 'read current time',
229
+ 'read current time',
230
+ 'read current time',
231
+ 'read current time',
232
+ ]);
233
+ }
234
}
235
});
236