@samitouri / QOS-React-2 / commits / c13986da78

Fix Overlapping "message" Bug in Performance Track (#31528)

When you schedule a microtask from render or effect and then call setState (or ping) from there, the "event" is the event that React scheduled (which will be a postMessage). The event time of this new render will be before the last render finished. We usually clamp these but in this scenario the update doesn't happen while a render is happening. Causing overlapping events. Before: <img width="1229" alt="Screenshot 2024-11-12 at 11 01 30 PM" src="https://github.com/user-attachments/assets/9652cf3b-b358-453c-b295-1239cbb15952"> Therefore when we finalize a render we need to store the end of the last render so when we a new update comes in later with an event time earlier than that, we know to clamp it. There's also a special case here where when we enter the `RootDidNotComplete` or `RootSuspendedWithDelay` case we neither leave the root as in progress nor commit it. Those needs to finalize too. Really this should be modeled as a suspended track that we haven't added yet. That's the gap between "Blocked" and "message" below. After: <img width="1471" alt="Screenshot 2024-11-13 at 12 31 34 AM" src="https://github.com/user-attachments/assets/b24f994e-9055-4b10-ad29-ad9b36302ffc"> I also fixed an issue where we may log the same event name multiple times if we're rendering more than once in the same event. In this case I just leave a blank trace between the last commit and the next update. I also adding ignoring of the "message" event at all in these cases when the event is from React's scheduling itself.

Sebastian Markbåge committed Nov 14, 2024 at 16:35 UTC c13986da7866a1a70a73b7ee05c87a9618ce6d03

12 files changed +97 -31

packages/react-art/src/ReactFiberConfigART.js

@@ -363,6 +363,8 @@ export function resolveUpdatePriority(): EventPriority {

363 return currentUpdatePriority || DefaultEventPriority;

364 }

365

366 +export function trackSchedulerEvent(): void {}

367 +

368 export function resolveEventType(): null | string {

369 return null;

370 }

packages/react-dom-bindings/src/client/ReactFiberConfigDOM.js

+7 -2

@@ -606,14 +606,19 @@ export function shouldAttemptEagerTransition(): boolean {

606 return false;

607 }

608

609 +let schedulerEvent: void | Event = undefined;

610 +export function trackSchedulerEvent(): void {

611 + schedulerEvent = window.event;

612 +}

613 +

614 export function resolveEventType(): null | string {

615 const event = window.event;

611 - return event ? event.type : null;

616 + return event && event !== schedulerEvent ? event.type : null;

617 }

618

619 export function resolveEventTimeStamp(): number {

620 const event = window.event;

616 - return event ? event.timeStamp : -1.1;

621 + return event && event !== schedulerEvent ? event.timeStamp : -1.1;

622 }

623

624 export const isPrimaryRenderer = true;

packages/react-native-renderer/src/ReactFiberConfigFabric.js

@@ -372,6 +372,8 @@ export function resolveUpdatePriority(): EventPriority {

372 return DefaultEventPriority;

373 }

374

375 +export function trackSchedulerEvent(): void {}

376 +

377 export function resolveEventType(): null | string {

378 return null;

379 }

packages/react-native-renderer/src/ReactFiberConfigNative.js

@@ -288,6 +288,8 @@ export function resolveUpdatePriority(): EventPriority {

288 return DefaultEventPriority;

289 }

290

291 +export function trackSchedulerEvent(): void {}

292 +

293 export function resolveEventType(): null | string {

294 return null;

295 }

packages/react-noop-renderer/src/createReactNoop.js

@@ -531,6 +531,8 @@ function createReactNoop(reconciler: Function, useMutation: boolean) {

531 return currentEventPriority;

532 },

533

534 + trackSchedulerEvent(): void {},

535 +

536 resolveEventType(): null | string {

537 return null;

538 },

packages/react-reconciler/src/ReactFiberPerformanceTrack.js

+4 -2

@@ -118,6 +118,7 @@ export function logBlockingStart(

118 updateTime: number,

119 eventTime: number,

120 eventType: null | string,

121 + eventIsRepeat: boolean,

122 renderStartTime: number,

123 ): void {

124 if (supportsUserTiming) {

@@ -127,7 +128,7 @@ export function logBlockingStart(

128 reusableLaneDevToolDetails.color = 'secondary-dark';

129 reusableLaneOptions.start = eventTime;

130 reusableLaneOptions.end = updateTime > 0 ? updateTime : renderStartTime;

130 - performance.measure(eventType, reusableLaneOptions);

131 + performance.measure(eventIsRepeat ? '' : eventType, reusableLaneOptions);

132 }

133 if (updateTime > 0) {

134 // Log the time from when we called setState until we started rendering.

@@ -144,6 +145,7 @@ export function logTransitionStart(

145 updateTime: number,

146 eventTime: number,

147 eventType: null | string,

148 + eventIsRepeat: boolean,

149 renderStartTime: number,

150 ): void {

151 if (supportsUserTiming) {

@@ -158,7 +160,7 @@ export function logTransitionStart(

160 : updateTime > 0

161 ? updateTime

162 : renderStartTime;

161 - performance.measure(eventType, reusableLaneOptions);

163 + performance.measure(eventIsRepeat ? '' : eventType, reusableLaneOptions);

164 }

165 if (startTime > 0) {

166 // Log the time from when we started an async transition until we called setState or started rendering.

packages/react-reconciler/src/ReactFiberRootScheduler.js

+14

@@ -18,6 +18,7 @@ import {

18 disableSchedulerTimeoutInWorkLoop,

19 enableProfilerTimer,

20 enableProfilerNestedUpdatePhase,

21 + enableComponentPerformanceTrack,

22 enableSiblingPrerendering,

23 } from 'shared/ReactFeatureFlags';

24 import {

@@ -64,6 +65,7 @@ import {

65 supportsMicrotasks,

66 scheduleMicrotask,

67 shouldAttemptEagerTransition,

68 + trackSchedulerEvent,

69 } from './ReactFiberConfig';

71 import ReactSharedInternals from 'shared/ReactSharedInternals';

@@ -225,6 +227,12 @@ function flushSyncWorkAcrossRoots_impl(

227 }

228

229 function processRootScheduleInMicrotask() {

230 + if (enableProfilerTimer && enableComponentPerformanceTrack) {

231 + // Track the currently executing event if there is one so we can ignore this

232 + // event when logging events.

233 + trackSchedulerEvent();

234 + }

235 +

236 // This function is always called inside a microtask. It should never be

237 // called synchronously.

238 didScheduleMicrotask = false;

@@ -428,6 +436,12 @@ function performWorkOnRootViaSchedulerTask(

436 resetNestedUpdateFlag();

437 }

438

439 + if (enableProfilerTimer && enableComponentPerformanceTrack) {

440 + // Track the currently executing event if there is one so we can ignore this

441 + // event when logging events.

442 + trackSchedulerEvent();

443 + }

444 +

445 // Flush any pending passive effects before deciding which lanes to work on,

446 // in case they schedule additional work.

447 const originalCallbackNode = root.callbackNode;

packages/react-reconciler/src/ReactFiberWorkLoop.js

+33 -5

@@ -90,6 +90,7 @@ import {

90 setCurrentUpdatePriority,

91 getCurrentUpdatePriority,

92 resolveUpdatePriority,

93 + trackSchedulerEvent,

94 } from './ReactFiberConfig';

96 import {createWorkInProgress, resetWorkInProgress} from './ReactFiber';

@@ -229,13 +230,17 @@ import {

230 } from './ReactFiberConcurrentUpdates';

231

232 import {

233 + blockingClampTime,

234 blockingUpdateTime,

235 blockingEventTime,

236 blockingEventType,

237 + blockingEventIsRepeat,

238 + transitionClampTime,

239 transitionStartTime,

240 transitionUpdateTime,

241 transitionEventTime,

242 transitionEventType,

243 + transitionEventIsRepeat,

244 clearBlockingTimers,

245 clearTransitionTimers,

246 clampBlockingTimers,

@@ -938,6 +943,9 @@ export function performWorkOnRoot(

943 }

944 break;

945 } else if (exitStatus === RootDidNotComplete) {

946 + if (enableProfilerTimer && enableComponentPerformanceTrack) {

947 + finalizeRender(lanes, now());

948 + }

949 // The render unwound without completing the tree. This happens in special

950 // cases where need to exit the current render without producing a

951 // consistent tree or committing.

@@ -1130,6 +1138,9 @@ function finishConcurrentRender(

1138 // This is a transition, so we should exit without committing a

1139 // placeholder and without scheduling a timeout. Delay indefinitely

1140 // until we receive more data.

1141 + if (enableProfilerTimer && enableComponentPerformanceTrack) {

1142 + finalizeRender(lanes, now());

1143 + }

1144 const didAttemptEntireTree =

1145 !workInProgressRootDidSkipSuspendedSiblings;

1146 markRootSuspended(

@@ -1655,19 +1666,31 @@ function prepareFreshStack(root: FiberRoot, lanes: Lanes): Fiber {

1666

1667 if (includesSyncLane(lanes) || includesBlockingLane(lanes)) {

1668 logBlockingStart(

1658 - blockingUpdateTime,

1659 - blockingEventTime,

1669 + blockingUpdateTime >= 0 && blockingUpdateTime < blockingClampTime

1670 + ? blockingClampTime

1671 + : blockingUpdateTime,

1672 + blockingEventTime >= 0 && blockingEventTime < blockingClampTime

1673 + ? blockingClampTime

1674 + : blockingEventTime,

1675 blockingEventType,

1676 + blockingEventIsRepeat,

1677 renderStartTime,

1678 );

1679 clearBlockingTimers();

1680 }

1681 if (includesTransitionLane(lanes)) {

1682 logTransitionStart(

1667 - transitionStartTime,

1668 - transitionUpdateTime,

1669 - transitionEventTime,

1683 + transitionStartTime >= 0 && transitionStartTime < transitionClampTime

1684 + ? transitionClampTime

1685 + : transitionStartTime,

1686 + transitionUpdateTime >= 0 && transitionUpdateTime < transitionClampTime

1687 + ? transitionClampTime

1688 + : transitionUpdateTime,

1689 + transitionEventTime >= 0 && transitionEventTime < transitionClampTime

1690 + ? transitionClampTime

1691 + : transitionEventTime,

1692 transitionEventType,

1693 + transitionEventIsRepeat,

1694 renderStartTime,

1695 );

1696 clearTransitionTimers();

@@ -3139,6 +3162,11 @@ function commitRootImpl(

3162 // with setTimeout

3163 pendingPassiveTransitions = transitions;

3164 scheduleCallback(NormalSchedulerPriority, () => {

3165 + if (enableProfilerTimer && enableComponentPerformanceTrack) {

3166 + // Track the currently executing event if there is one so we can ignore this

3167 + // event when logging events.

3168 + trackSchedulerEvent();

3169 + }

3170 flushPassiveEffects(true);

3171 // This render triggered passive effects: release the root cache pool

3172 // *after* passive effects fire to avoid freeing a cache pool that may

packages/react-reconciler/src/ReactProfilerTimer.js

+27 -21

@@ -36,14 +36,18 @@ export let componentEffectDuration: number = -0;

36 export let componentEffectStartTime: number = -1.1;

37 export let componentEffectEndTime: number = -1.1;

39 +export let blockingClampTime: number = -0;

40 export let blockingUpdateTime: number = -1.1; // First sync setState scheduled.

41 export let blockingEventTime: number = -1.1; // Event timeStamp of the first setState.

42 export let blockingEventType: null | string = null; // Event type of the first setState.

43 +export let blockingEventIsRepeat: boolean = false;

44 // TODO: This should really be one per Transition lane.

45 +export let transitionClampTime: number = -0;

46 export let transitionStartTime: number = -1.1; // First startTransition call before setState.

47 export let transitionUpdateTime: number = -1.1; // First transition setState scheduled.

48 export let transitionEventTime: number = -1.1; // Event timeStamp of the first transition.

49 export let transitionEventType: null | string = null; // Event type of the first transition.

50 +export let transitionEventIsRepeat: boolean = false;

52 export function startUpdateTimerByLane(lane: Lane): void {

53 if (!enableProfilerTimer || !enableComponentPerformanceTrack) {

@@ -52,15 +56,25 @@ export function startUpdateTimerByLane(lane: Lane): void {

56 if (isSyncLane(lane) || isBlockingLane(lane)) {

57 if (blockingUpdateTime < 0) {

58 blockingUpdateTime = now();

55 - blockingEventTime = resolveEventTimeStamp();

56 - blockingEventType = resolveEventType();

59 + const newEventTime = resolveEventTimeStamp();

60 + const newEventType = resolveEventType();

61 + blockingEventIsRepeat =

62 + newEventTime === blockingEventTime &&

63 + newEventType === blockingEventType;

64 + blockingEventTime = newEventTime;

65 + blockingEventType = newEventType;

66 }

67 } else if (isTransitionLane(lane)) {

68 if (transitionUpdateTime < 0) {

69 transitionUpdateTime = now();

70 if (transitionStartTime < 0) {

62 - transitionEventTime = resolveEventTimeStamp();

63 - transitionEventType = resolveEventType();

71 + const newEventTime = resolveEventTimeStamp();

72 + const newEventType = resolveEventType();

73 + transitionEventIsRepeat =

74 + newEventTime === transitionEventTime &&

75 + newEventType === transitionEventType;

76 + transitionEventTime = newEventTime;

77 + transitionEventType = newEventType;

78 }

79 }

80 }

@@ -76,8 +90,13 @@ export function startAsyncTransitionTimer(): void {

90 }

91 if (transitionStartTime < 0 && transitionUpdateTime < 0) {

92 transitionStartTime = now();

79 - transitionEventTime = resolveEventTimeStamp();

80 - transitionEventType = resolveEventType();

93 + const newEventTime = resolveEventTimeStamp();

94 + const newEventType = resolveEventType();

95 + transitionEventIsRepeat =

96 + newEventTime === transitionEventTime &&

97 + newEventType === transitionEventType;

98 + transitionEventTime = newEventTime;

99 + transitionEventType = newEventType;

100 }

101 }

102

@@ -115,12 +134,7 @@ export function clampBlockingTimers(finalTime: number): void {

134 // If we had new updates come in while we were still rendering or committing, we don't want

135 // those update times to create overlapping tracks in the performance timeline so we clamp

136 // them to the end of the commit phase.

118 - if (blockingUpdateTime >= 0 && blockingUpdateTime < finalTime) {

119 - blockingUpdateTime = finalTime;

120 - }

121 - if (blockingEventTime >= 0 && blockingEventTime < finalTime) {

122 - blockingEventTime = finalTime;

123 - }

137 + blockingClampTime = finalTime;

138 }

139

140 export function clampTransitionTimers(finalTime: number): void {

@@ -130,15 +144,7 @@ export function clampTransitionTimers(finalTime: number): void {

144 // If we had new updates come in while we were still rendering or committing, we don't want

145 // those update times to create overlapping tracks in the performance timeline so we clamp

146 // them to the end of the commit phase.

133 - if (transitionStartTime >= 0 && transitionStartTime < finalTime) {

134 - transitionStartTime = finalTime;

135 - }

136 - if (transitionUpdateTime >= 0 && transitionUpdateTime < finalTime) {

137 - transitionUpdateTime = finalTime;

138 - }

139 - if (transitionEventTime >= 0 && transitionEventTime < finalTime) {

140 - transitionEventTime = finalTime;

141 - }

147 + transitionClampTime = finalTime;

148 }

149

150 export function pushNestedEffectDurations(): number {

packages/react-reconciler/src/__tests__/ReactFiberHostContext-test.internal.js

@@ -83,6 +83,7 @@ describe('ReactFiberHostContext', () => {

83 }

84 return DefaultEventPriority;

85 },

86 + trackSchedulerEvent: function () {},

87 resolveEventType: function () {

88 return null;

89 },

packages/react-reconciler/src/forks/ReactFiberConfig.custom.js

@@ -73,6 +73,7 @@ export const getInstanceFromScope = $$$config.getInstanceFromScope;

73 export const setCurrentUpdatePriority = $$$config.setCurrentUpdatePriority;

74 export const getCurrentUpdatePriority = $$$config.getCurrentUpdatePriority;

75 export const resolveUpdatePriority = $$$config.resolveUpdatePriority;

76 +export const trackSchedulerEvent = $$$config.trackSchedulerEvent;

77 export const resolveEventType = $$$config.resolveEventType;

78 export const resolveEventTimeStamp = $$$config.resolveEventTimeStamp;

79 export const shouldAttemptEagerTransition =

packages/react-test-renderer/src/ReactFiberConfigTestHost.js

+2 -1

@@ -224,10 +224,11 @@ export function resolveUpdatePriority(): EventPriority {

224 }

225 return DefaultEventPriority;

226 }

227 +

228 +export function trackSchedulerEvent(): void {}

229 export function resolveEventType(): null | string {

230 return null;

231 }

230 -

232 export function resolveEventTimeStamp(): number {

233 return -1.1;

234 }