@samitouri / QOS-React-1 / commits / e1c20902c3

[Fiber] Log Component Effects to Performance Track (#30983)

Stacked on #30981. Same as #30967 but for effects. This logs a tree of components using `performance.measure()`. In addition to the previous render phase this logs one tree for each commit phase: - Mutation Phase - Layout Effect - Passive Unmounts - Passive Mounts I currently skip the Before Mutation phase since the snapshots are so unusual it's not worth creating trees for those. The mechanism is that I reuse the timings we track for `enableProfilerCommitHooks`. I track first and last effect timestamp within each component subtree. Then on the way up do we log the entry. This means that we don't include overhead to find our way down to a component and that we don't need to add any additional overhead by reading timestamps. To ensure that the entries get ordered correctly we need to ensure that the start time of each parent is slightly before the inner one.

Sebastian Markbåge committed Sep 17, 2024 at 16:14 UTC e1c20902c39d1dfe2649185622f2f21b526e2be2

3 files changed +215 -88

packages/react-reconciler/src/ReactFiberCommitWork.js

+112 -22

@@ -99,13 +99,21 @@ import {

99 Cloned,

100 } from './ReactFiberFlags';

101 import {

102 - getCommitTime,

103 - getCompleteTime,

102 + commitTime,

103 + completeTime,

104 pushNestedEffectDurations,

105 popNestedEffectDurations,

106 bubbleNestedEffectDurations,

107 + resetComponentEffectTimers,

108 + pushComponentEffectStart,

109 + popComponentEffectStart,

110 + componentEffectStartTime,

111 + componentEffectEndTime,

112 } from './ReactProfilerTimer';

108 -import {logComponentRender} from './ReactFiberPerformanceTrack';

113 +import {

114 + logComponentRender,

115 + logComponentEffect,

116 +} from './ReactFiberPerformanceTrack';

117 import {ConcurrentMode, NoMode, ProfileMode} from './ReactTypeOfMode';

118 import {deferHiddenCallbacks} from './ReactFiberClassUpdateQueue';

119 import {

@@ -382,6 +390,8 @@ function commitLayoutEffectOnFiber(

390 finishedWork: Fiber,

391 committedLanes: Lanes,

392 ): void {

393 + const prevEffectStart = pushComponentEffectStart();

394 +

395 // When updating this function, also update reappearLayoutEffects, which does

396 // most of the same things when an offscreen tree goes from hidden -> visible.

397 const flags = finishedWork.flags;

@@ -494,7 +504,7 @@ function commitLayoutEffectOnFiber(

504 commitProfilerUpdate(

505 finishedWork,

506 current,

497 - getCommitTime(),

507 + commitTime,

508 profilerInstance.effectDuration,

509 );

510 } else {

@@ -585,6 +595,23 @@ function commitLayoutEffectOnFiber(

595 break;

596 }

597 }

598 +

599 + if (

600 + enableProfilerTimer &&

601 + enableProfilerCommitHooks &&

602 + enableComponentPerformanceTrack &&

603 + (finishedWork.mode & ProfileMode) !== NoMode &&

604 + componentEffectStartTime >= 0 &&

605 + componentEffectEndTime >= 0

606 + ) {

607 + logComponentEffect(

608 + finishedWork,

609 + componentEffectStartTime,

610 + componentEffectEndTime,

611 + );

612 + }

613 +

614 + popComponentEffectStart(prevEffectStart);

615 }

616

617 function abortRootTransitions(

@@ -1530,6 +1557,8 @@ export function commitMutationEffects(

1557 inProgressLanes = committedLanes;

1558 inProgressRoot = root;

1559

1560 + resetComponentEffectTimers();

1561 +

1562 commitMutationEffectsOnFiber(finishedWork, root, committedLanes);

1563

1564 inProgressLanes = null;

@@ -1570,6 +1599,8 @@ function commitMutationEffectsOnFiber(

1599 root: FiberRoot,

1600 lanes: Lanes,

1601 ) {

1602 + const prevEffectStart = pushComponentEffectStart();

1603 +

1604 const current = finishedWork.alternate;

1605 const flags = finishedWork.flags;

1606

@@ -1598,7 +1629,7 @@ function commitMutationEffectsOnFiber(

1629 HookLayout | HookHasEffect,

1630 );

1631 }

1601 - return;

1632 + break;

1633 }

1634 case ClassComponent: {

1635 recursivelyTraverseMutationEffects(root, finishedWork, lanes);

@@ -1617,7 +1648,7 @@ function commitMutationEffectsOnFiber(

1648 deferHiddenCallbacks(updateQueue);

1649 }

1650 }

1620 - return;

1651 + break;

1652 }

1653 case HostHoistable: {

1654 if (supportsResources) {

@@ -1693,7 +1724,7 @@ function commitMutationEffectsOnFiber(

1724 );

1725 }

1726 }

1696 - return;

1727 + break;

1728 }

1729 // Fall through

1730 }

@@ -1756,7 +1787,7 @@ function commitMutationEffectsOnFiber(

1787 }

1788 }

1789 }

1759 - return;

1790 + break;

1791 }

1792 case HostText: {

1793 recursivelyTraverseMutationEffects(root, finishedWork, lanes);

@@ -1781,7 +1812,7 @@ function commitMutationEffectsOnFiber(

1812 commitHostTextUpdate(finishedWork, newText, oldText);

1813 }

1814 }

1784 - return;

1815 + break;

1816 }

1817 case HostRoot: {

1818 const prevEffectDuration = pushNestedEffectDurations();

@@ -1833,7 +1864,7 @@ function commitMutationEffectsOnFiber(

1864 root.effectDuration += popNestedEffectDurations(prevEffectDuration);

1865 }

1866

1836 - return;

1867 + break;

1868 }

1869 case HostPortal: {

1870 if (supportsResources) {

@@ -1858,7 +1889,7 @@ function commitMutationEffectsOnFiber(

1889 );

1890 }

1891 }

1861 - return;

1892 + break;

1893 }

1894 case Profiler: {

1895 const prevEffectDuration = pushNestedEffectDurations();

@@ -1873,7 +1904,7 @@ function commitMutationEffectsOnFiber(

1904 profilerInstance.effectDuration +=

1905 bubbleNestedEffectDurations(prevEffectDuration);

1906 }

1876 - return;

1907 + break;

1908 }

1909 case SuspenseComponent: {

1910 recursivelyTraverseMutationEffects(root, finishedWork, lanes);

@@ -1925,7 +1956,7 @@ function commitMutationEffectsOnFiber(

1956 attachSuspenseRetryListeners(finishedWork, retryQueue);

1957 }

1958 }

1928 - return;

1959 + break;

1960 }

1961 case OffscreenComponent: {

1962 if (flags & Ref) {

@@ -2018,7 +2049,7 @@ function commitMutationEffectsOnFiber(

2049 }

2050 }

2051 }

2021 - return;

2052 + break;

2053 }

2054 case SuspenseListComponent: {

2055 recursivelyTraverseMutationEffects(root, finishedWork, lanes);

@@ -2032,7 +2063,7 @@ function commitMutationEffectsOnFiber(

2063 attachSuspenseRetryListeners(finishedWork, retryQueue);

2064 }

2065 }

2035 - return;

2066 + break;

2067 }

2068 case ScopeComponent: {

2069 if (enableScopeAPI) {

@@ -2052,16 +2083,34 @@ function commitMutationEffectsOnFiber(

2083 prepareScopeUpdate(scopeInstance, finishedWork);

2084 }

2085 }

2055 - return;

2086 + break;

2087 }

2088 default: {

2089 recursivelyTraverseMutationEffects(root, finishedWork, lanes);

2090 commitReconciliationEffects(finishedWork);

2091

2061 - return;

2092 + break;

2093 }

2094 }

2095 +

2096 + if (

2097 + enableProfilerTimer &&

2098 + enableProfilerCommitHooks &&

2099 + enableComponentPerformanceTrack &&

2100 + (finishedWork.mode & ProfileMode) !== NoMode &&

2101 + componentEffectStartTime >= 0 &&

2102 + componentEffectEndTime >= 0

2103 + ) {

2104 + logComponentEffect(

2105 + finishedWork,

2106 + componentEffectStartTime,

2107 + componentEffectEndTime,

2108 + );

2109 + }

2110 +

2111 + popComponentEffectStart(prevEffectStart);

2112 }

2113 +

2114 function commitReconciliationEffects(finishedWork: Fiber) {

2115 // Placement effects (insertions, reorders) can be scheduled on any fiber

2116 // type. They needs to happen after the children effects have fired, but

@@ -2106,6 +2155,8 @@ export function commitLayoutEffects(

2155 inProgressLanes = committedLanes;

2156 inProgressRoot = root;

2157

2158 + resetComponentEffectTimers();

2159 +

2160 const current = finishedWork.alternate;

2161 commitLayoutEffectOnFiber(root, current, finishedWork, committedLanes);

2162

@@ -2291,7 +2342,7 @@ export function reappearLayoutEffects(

2342 commitProfilerUpdate(

2343 finishedWork,

2344 current,

2294 - getCommitTime(),

2345 + commitTime,

2346 profilerInstance.effectDuration,

2347 );

2348 } else {

@@ -2515,14 +2566,14 @@ export function commitPassiveMountEffects(

2566 committedLanes: Lanes,

2567 committedTransitions: Array<Transition> | null,

2568 ): void {

2569 + resetComponentEffectTimers();

2570 +

2571 commitPassiveMountOnFiber(

2572 root,

2573 finishedWork,

2574 committedLanes,

2575 committedTransitions,

2523 - enableProfilerTimer && enableComponentPerformanceTrack

2524 - ? getCompleteTime()

2525 - : 0,

2576 + enableProfilerTimer && enableComponentPerformanceTrack ? completeTime : 0,

2577 );

2578 }

2579

@@ -2577,6 +2628,8 @@ function commitPassiveMountOnFiber(

2628 committedTransitions: Array<Transition> | null,

2629 endTime: number, // Profiling-only. The start time of the next Fiber or root completion.

2630 ): void {

2631 + const prevEffectStart = pushComponentEffectStart();

2632 +

2633 // If this component rendered in Profiling mode (DEV or in Profiler component) then log its

2634 // render time. We do this after the fact in the passive effect to avoid the overhead of this

2635 // getting in the way of the render characteristics and avoid the overhead of unwinding

@@ -2707,7 +2760,7 @@ function commitPassiveMountOnFiber(

2760 finishedWork.alternate,

2761 // This value will still reflect the previous commit phase.

2762 // It does not get reset until the start of the next commit phase.

2710 - getCommitTime(),

2763 + commitTime,

2764 profilerInstance.passiveEffectDuration,

2765 );

2766 } else {

@@ -2860,6 +2913,23 @@ function commitPassiveMountOnFiber(

2913 break;

2914 }

2915 }

2916 +

2917 + if (

2918 + enableProfilerTimer &&

2919 + enableProfilerCommitHooks &&

2920 + enableComponentPerformanceTrack &&

2921 + (finishedWork.mode & ProfileMode) !== NoMode &&

2922 + componentEffectStartTime >= 0 &&

2923 + componentEffectEndTime >= 0

2924 + ) {

2925 + logComponentEffect(

2926 + finishedWork,

2927 + componentEffectStartTime,

2928 + componentEffectEndTime,

2929 + );

2930 + }

2931 +

2932 + popComponentEffectStart(prevEffectStart);

2933 }

2934

2935 function recursivelyTraverseReconnectPassiveEffects(

@@ -3131,6 +3201,7 @@ function commitAtomicPassiveEffects(

3201 }

3202

3203 export function commitPassiveUnmountEffects(finishedWork: Fiber): void {

3204 + resetComponentEffectTimers();

3205 commitPassiveUnmountOnFiber(finishedWork);

3206 }

3207

@@ -3289,6 +3360,8 @@ function recursivelyTraversePassiveUnmountEffects(parentFiber: Fiber): void {

3360 }

3361

3362 function commitPassiveUnmountOnFiber(finishedWork: Fiber): void {

3363 + const prevEffectStart = pushComponentEffectStart();

3364 +

3365 switch (finishedWork.tag) {

3366 case FunctionComponent:

3367 case ForwardRef:

@@ -3358,6 +3431,23 @@ function commitPassiveUnmountOnFiber(finishedWork: Fiber): void {

3431 break;

3432 }

3433 }

3434 +

3435 + if (

3436 + enableProfilerTimer &&

3437 + enableProfilerCommitHooks &&

3438 + enableComponentPerformanceTrack &&

3439 + (finishedWork.mode & ProfileMode) !== NoMode &&

3440 + componentEffectStartTime >= 0 &&

3441 + componentEffectEndTime >= 0

3442 + ) {

3443 + logComponentEffect(

3444 + finishedWork,

3445 + componentEffectStartTime,

3446 + componentEffectEndTime,

3447 + );

3448 + }

3449 +

3450 + popComponentEffectStart(prevEffectStart);

3451 }

3452

3453 function recursivelyTraverseDisconnectPassiveEffects(parentFiber: Fiber): void {

packages/react-reconciler/src/ReactFiberPerformanceTrack.js

+34 -2

@@ -38,9 +38,24 @@ const reusableComponentOptions = {

38 },

39 };

41 +const reusableComponentEffectDevToolDetails = {

42 + dataType: 'track-entry',

43 + color: 'secondary',

44 + track: 'Blocking', // Lane

45 + trackGroup: TRACK_GROUP,

46 +};

47 +const reusableComponentEffectOptions = {

48 + start: -0,

49 + end: -0,

50 + detail: {

51 + devtools: reusableComponentEffectDevToolDetails,

52 + },

53 +};

54 +

55 export function setCurrentTrackFromLanes(lanes: number): void {

42 - reusableComponentDevToolDetails.track =

43 - getGroupNameOfHighestPriorityLane(lanes);

56 + reusableComponentEffectDevToolDetails.track =

57 + reusableComponentDevToolDetails.track =

58 + getGroupNameOfHighestPriorityLane(lanes);

59 }

61 export function logComponentRender(

@@ -59,3 +74,20 @@ export function logComponentRender(

74 performance.measure(name, reusableComponentOptions);

75 }

76 }

77 +

78 +export function logComponentEffect(

79 + fiber: Fiber,

80 + startTime: number,

81 + endTime: number,

82 +): void {

83 + const name = getComponentNameFromFiber(fiber);

84 + if (name === null) {

85 + // Skip

86 + return;

87 + }

88 + if (supportsUserTiming) {

89 + reusableComponentEffectOptions.start = startTime;

90 + reusableComponentEffectOptions.end = endTime;

91 + performance.measure(name, reusableComponentEffectOptions);

92 + }

93 +}

packages/react-reconciler/src/ReactProfilerTimer.js

+69 -64

@@ -21,25 +21,14 @@ import * as Scheduler from 'scheduler';

22 const {unstable_now: now} = Scheduler;

24 -export type ProfilerTimer = {

25 - getCommitTime(): number,

26 - isCurrentUpdateNested(): boolean,

27 - markNestedUpdateScheduled(): void,

28 - recordCommitTime(): void,

29 - startProfilerTimer(fiber: Fiber): void,

30 - stopProfilerTimerIfRunning(fiber: Fiber): void,

31 - stopProfilerTimerIfRunningAndRecordDuration(fiber: Fiber): void,

32 - stopProfilerTimerIfRunningAndRecordIncompleteDuration(fiber: Fiber): void,

33 - syncNestedUpdateFlag(): void,

34 - ...

35 -};

36 -

37 -let completeTime: number = -0;

38 -let commitTime: number = -0;

39 -let profilerStartTime: number = -1.1;

40 -let profilerEffectDuration: number = -0;

41 -

42 -function pushNestedEffectDurations(): number {

24 +export let completeTime: number = -0;

25 +export let commitTime: number = -0;

26 +export let profilerStartTime: number = -1.1;

27 +export let profilerEffectDuration: number = -0;

28 +export let componentEffectStartTime: number = -1.1;

29 +export let componentEffectEndTime: number = -1.1;

30 +

31 +export function pushNestedEffectDurations(): number {

32 if (!enableProfilerTimer || !enableProfilerCommitHooks) {

33 return 0;

34 }

@@ -48,7 +37,7 @@ function pushNestedEffectDurations(): number {

37 return prevEffectDuration;

38 }

51 -function popNestedEffectDurations(prevEffectDuration: number): number {

40 +export function popNestedEffectDurations(prevEffectDuration: number): number {

41 if (!enableProfilerTimer || !enableProfilerCommitHooks) {

42 return 0;

43 }

@@ -58,7 +47,9 @@ function popNestedEffectDurations(prevEffectDuration: number): number {

47 }

49 // Like pop but it also adds the current elapsed time to the parent scope.

61 -function bubbleNestedEffectDurations(prevEffectDuration: number): number {

50 +export function bubbleNestedEffectDurations(

51 + prevEffectDuration: number,

52 +): number {

53 if (!enableProfilerTimer || !enableProfilerCommitHooks) {

54 return 0;

55 }

@@ -67,6 +58,39 @@ function bubbleNestedEffectDurations(prevEffectDuration: number): number {

58 return elapsedTime;

59 }

61 +export function resetComponentEffectTimers(): void {

62 + if (!enableProfilerTimer || !enableProfilerCommitHooks) {

63 + return;

64 + }

65 + componentEffectStartTime = -1.1;

66 + componentEffectEndTime = -1.1;

67 +}

68 +

69 +export function pushComponentEffectStart(): number {

70 + if (!enableProfilerTimer || !enableProfilerCommitHooks) {

71 + return 0;

72 + }

73 + const prevEffectStart = componentEffectStartTime;

74 + componentEffectStartTime = -1.1; // Track the next start.

75 + return prevEffectStart;

76 +}

77 +

78 +export function popComponentEffectStart(prevEffectStart: number): void {

79 + if (!enableProfilerTimer || !enableProfilerCommitHooks) {

80 + return;

81 + }

82 + if (prevEffectStart < 0) {

83 + // If the parent component didn't have a start time, we use the start

84 + // of the child as the parent's start time. We subtrack a minimal amount of

85 + // time to ensure that the parent's start time is before the child to ensure

86 + // that the performance tracks line up in the right order.

87 + componentEffectStartTime -= 0.001;

88 + } else {

89 + // Otherwise, we restore the previous parent's start time.

90 + componentEffectStartTime = prevEffectStart;

91 + }

92 +}

93 +

94 /**

95 * Tracks whether the current update was a nested/cascading update (scheduled from a layout effect).

96 *

@@ -86,53 +110,45 @@ function bubbleNestedEffectDurations(prevEffectDuration: number): number {

110 let currentUpdateIsNested: boolean = false;

111 let nestedUpdateScheduled: boolean = false;

112

89 -function isCurrentUpdateNested(): boolean {

113 +export function isCurrentUpdateNested(): boolean {

114 return currentUpdateIsNested;

115 }

116

93 -function markNestedUpdateScheduled(): void {

117 +export function markNestedUpdateScheduled(): void {

118 if (enableProfilerNestedUpdatePhase) {

119 nestedUpdateScheduled = true;

120 }

121 }

122

99 -function resetNestedUpdateFlag(): void {

123 +export function resetNestedUpdateFlag(): void {

124 if (enableProfilerNestedUpdatePhase) {

125 currentUpdateIsNested = false;

126 nestedUpdateScheduled = false;

127 }

128 }

129

106 -function syncNestedUpdateFlag(): void {

130 +export function syncNestedUpdateFlag(): void {

131 if (enableProfilerNestedUpdatePhase) {

132 currentUpdateIsNested = nestedUpdateScheduled;

133 nestedUpdateScheduled = false;

134 }

135 }

136

113 -function getCompleteTime(): number {

114 - return completeTime;

115 -}

116 -

117 -function recordCompleteTime(): void {

137 +export function recordCompleteTime(): void {

138 if (!enableProfilerTimer) {

139 return;

140 }

141 completeTime = now();

142 }

143

124 -function getCommitTime(): number {

125 - return commitTime;

126 -}

127 -

128 -function recordCommitTime(): void {

144 +export function recordCommitTime(): void {

145 if (!enableProfilerTimer) {

146 return;

147 }

148 commitTime = now();

149 }

150

135 -function startProfilerTimer(fiber: Fiber): void {

151 +export function startProfilerTimer(fiber: Fiber): void {

152 if (!enableProfilerTimer) {

153 return;

154 }

@@ -144,14 +160,16 @@ function startProfilerTimer(fiber: Fiber): void {

160 }

161 }

162

147 -function stopProfilerTimerIfRunning(fiber: Fiber): void {

163 +export function stopProfilerTimerIfRunning(fiber: Fiber): void {

164 if (!enableProfilerTimer) {

165 return;

166 }

167 profilerStartTime = -1;

168 }

169

154 -function stopProfilerTimerIfRunningAndRecordDuration(fiber: Fiber): void {

170 +export function stopProfilerTimerIfRunningAndRecordDuration(

171 + fiber: Fiber,

172 +): void {

173 if (!enableProfilerTimer) {

174 return;

175 }

@@ -164,7 +182,7 @@ function stopProfilerTimerIfRunningAndRecordDuration(fiber: Fiber): void {

182 }

183 }

184

167 -function stopProfilerTimerIfRunningAndRecordIncompleteDuration(

185 +export function stopProfilerTimerIfRunningAndRecordIncompleteDuration(

186 fiber: Fiber,

187 ): void {

188 if (!enableProfilerTimer) {

@@ -179,30 +197,38 @@ function stopProfilerTimerIfRunningAndRecordIncompleteDuration(

197 }

198 }

199

182 -function recordEffectDuration(fiber: Fiber): void {

200 +export function recordEffectDuration(fiber: Fiber): void {

201 if (!enableProfilerTimer || !enableProfilerCommitHooks) {

202 return;

203 }

204

205 if (profilerStartTime >= 0) {

188 - const elapsedTime = now() - profilerStartTime;

206 + const endTime = now();

207 + const elapsedTime = endTime - profilerStartTime;

208

209 profilerStartTime = -1;

210

211 // Store duration on the next nearest Profiler ancestor

212 // Or the root (for the DevTools Profiler to read)

213 profilerEffectDuration += elapsedTime;

214 +

215 + // Keep track of the last end time of the effects.

216 + componentEffectEndTime = endTime;

217 }

218 }

219

198 -function startEffectTimer(): void {

220 +export function startEffectTimer(): void {

221 if (!enableProfilerTimer || !enableProfilerCommitHooks) {

222 return;

223 }

224 profilerStartTime = now();

225 + if (componentEffectStartTime < 0) {

226 + // Keep track of the first time we start an effect as the component's effect start time.

227 + componentEffectStartTime = profilerStartTime;

228 + }

229 }

230

205 -function transferActualDuration(fiber: Fiber): void {

231 +export function transferActualDuration(fiber: Fiber): void {

232 // Transfer time spent rendering these children so we don't lose it

233 // after we rerender. This is used as a helper in special cases

234 // where we should count the work of multiple passes.

@@ -213,24 +239,3 @@ function transferActualDuration(fiber: Fiber): void {

239 child = child.sibling;

240 }

241 }

216 -

217 -export {

218 - getCompleteTime,

219 - recordCompleteTime,

220 - getCommitTime,

221 - recordCommitTime,

222 - isCurrentUpdateNested,

223 - markNestedUpdateScheduled,

224 - recordEffectDuration,

225 - resetNestedUpdateFlag,

226 - startEffectTimer,

227 - startProfilerTimer,

228 - stopProfilerTimerIfRunning,

229 - stopProfilerTimerIfRunningAndRecordDuration,

230 - stopProfilerTimerIfRunningAndRecordIncompleteDuration,

231 - syncNestedUpdateFlag,

232 - transferActualDuration,

233 - pushNestedEffectDurations,

234 - popNestedEffectDurations,

235 - bubbleNestedEffectDurations,

236 -};