@samitouri / QOS-React / commits / 9faf389e79

Reset profiler timer correctly after errors (#13123)

* Reset ReactProfilerTimer's DEV-only Fiber stack after an error * Added ReactNoop functionality to error during "complete" phase * Added failing profiler stack unwinding test * Potential fix for unwinding time bug * Renamed test * Don't record time until complete phase succeeds. Simplifies unwinding. * Expanded ReactProfilerDevToolsIntegration-test coverage a bit * Added unstable_flushWithoutCommitting method to noop renderer * Added failing multi-root/batch test to ReactProfiler-test * Beefed up tests a bit and added some TODOs * Profiler timer differentiates between batched commits and in-progress async work This was a two-part change: 1) Don't count time spent working on a batched commit against yielded async work. 2) Don't assert an empty stack after processing a batched commit (because there may be yielded async work) This is kind of a hacky solution, and may have problems that I haven't thought of yet. I need to commit this so I can mentally clock out for a bit without worrying about it. I will think about it more when I'm back from PTO. In the meanwhile, input is welcome. * Removed TODO * Replaced FiberRoot map with boolean * Removed unnecessary whitespace edit

Brian Vaughn committed Jul 5, 2018 at 11:38 UTC 9faf389e79c647d7792e631f3d8e9a9ce1a70625
9 files changed +260 -57
packages/react-noop-renderer/src/createReactNoop.js
+41 -1
@@ -43,6 +43,7 @@ function createReactNoop(reconciler: Function, useMutation: boolean) {
43
44 let instanceCounter = 0;
45 let failInBeginPhase = false;
46 + let failInCompletePhase = false;
47
48 function appendChild(
49 parentInstance: Instance | Container,
@@ -101,6 +102,9 @@ function createReactNoop(reconciler: Function, useMutation: boolean) {
102 },
103
104 createInstance(type: string, props: Props): Instance {
105 + if (failInCompletePhase) {
106 + throw new Error('Error in host config.');
107 + }
108 const inst = {
109 id: instanceCounter++,
110 type: type,
@@ -606,7 +610,7 @@ function createReactNoop(reconciler: Function, useMutation: boolean) {
610 console.log(...bufferedLog);
611 },
612
609 - simulateErrorInHostConfig(fn: () => void) {
613 + simulateErrorInHostConfigDuringBeginPhase(fn: () => void) {
614 failInBeginPhase = true;
615 try {
616 fn();
@@ -614,6 +618,42 @@ function createReactNoop(reconciler: Function, useMutation: boolean) {
618 failInBeginPhase = false;
619 }
620 },
621 +
622 + simulateErrorInHostConfigDuringCompletePhase(fn: () => void) {
623 + failInCompletePhase = true;
624 + try {
625 + fn();
626 + } finally {
627 + failInCompletePhase = false;
628 + }
629 + },
630 +
631 + flushWithoutCommitting(
632 + expectedFlush: Array<mixed>,
633 + rootID: string = DEFAULT_ROOT_ID,
634 + ) {
635 + const root: any = roots.get(rootID);
636 + const batch = {
637 + _defer: true,
638 + _expirationTime: 1,
639 + _onComplete: () => {
640 + root.firstBatch = null;
641 + },
642 + _next: null,
643 + };
644 + root.firstBatch = batch;
645 + const actual = ReactNoop.flush();
646 + expect(actual).toEqual(expectedFlush);
647 + return (expectedCommit: Array<mixed>) => {
648 + batch._defer = false;
649 + NoopRenderer.flushRoot(root, 1);
650 + expect(yieldedValues).toEqual(expectedCommit);
651 + };
652 + },
653 +
654 + getRoot(rootID: string = DEFAULT_ROOT_ID) {
655 + return roots.get(rootID);
656 + },
657 };
658
659 return ReactNoop;
packages/react-reconciler/src/ReactFiberCompleteWork.js
+26 -21
@@ -314,19 +314,13 @@ function completeWork(
314 ): Fiber | null {
315 const newProps = workInProgress.pendingProps;
316
317 - if (enableProfilerTimer) {
318 - if (workInProgress.mode & ProfileMode) {
319 - recordElapsedActualRenderTime(workInProgress);
320 - }
321 - }
322 -
317 switch (workInProgress.tag) {
318 case FunctionalComponent:
325 - return null;
319 + break;
320 case ClassComponent: {
321 // We are leaving this subtree, so pop context if any.
322 popLegacyContextProvider(workInProgress);
329 - return null;
323 + break;
324 }
325 case HostRoot: {
326 popHostContainer(workInProgress);
@@ -345,7 +339,7 @@ function completeWork(
339 workInProgress.effectTag &= ~Placement;
340 }
341 updateHostContainer(workInProgress);
348 - return null;
342 + break;
343 }
344 case HostComponent: {
345 popHostContext(workInProgress);
@@ -395,7 +389,7 @@ function completeWork(
389 'caused by a bug in React. Please file an issue.',
390 );
391 // This can happen when we abort work.
398 - return null;
392 + break;
393 }
394
395 const currentHostContext = getHostContext();
@@ -451,7 +445,7 @@ function completeWork(
445 markRef(workInProgress);
446 }
447 }
454 - return null;
448 + break;
449 }
450 case HostText: {
451 let newText = newProps;
@@ -468,7 +462,6 @@ function completeWork(
462 'caused by a bug in React. Please file an issue.',
463 );
464 // This can happen when we abort work.
471 - return null;
465 }
466 const rootContainerInstance = getRootHostContainer();
467 const currentHostContext = getHostContext();
@@ -486,28 +479,28 @@ function completeWork(
479 );
480 }
481 }
489 - return null;
482 + break;
483 }
484 case ForwardRef:
492 - return null;
485 + break;
486 case PlaceholderComponent:
494 - return null;
487 + break;
488 case Fragment:
496 - return null;
489 + break;
490 case Mode:
498 - return null;
491 + break;
492 case Profiler:
500 - return null;
493 + break;
494 case HostPortal:
495 popHostContainer(workInProgress);
496 updateHostContainer(workInProgress);
504 - return null;
497 + break;
498 case ContextProvider:
499 // Pop provider fiber
500 popProvider(workInProgress);
508 - return null;
501 + break;
502 case ContextConsumer:
510 - return null;
503 + break;
504 // Error cases
505 case IndeterminateComponent:
506 invariant(
@@ -524,6 +517,18 @@ function completeWork(
517 'React. Please file an issue.',
518 );
519 }
520 +
521 + if (enableProfilerTimer) {
522 + if (workInProgress.mode & ProfileMode) {
523 + // Don't record elapsed time unless the "complete" phase has succeeded.
524 + // Certain renderers may error during this phase (i.e. ReactNative View/Text nesting validation).
525 + // If an error occurs, we'll mark the time while unwinding.
526 + // This simplifies the unwinding logic and ensures consistency.
527 + recordElapsedActualRenderTime(workInProgress);
528 + }
529 + }
530 +
531 + return null;
532 }
533
534 export {completeWork};
packages/react-reconciler/src/ReactFiberScheduler.js
+19 -5
@@ -118,7 +118,7 @@ import {
118 recordCommitTime,
119 recordElapsedActualRenderTime,
120 recordElapsedBaseRenderTimeIfRunning,
121 - resetActualRenderTimer,
121 + resetActualRenderTimerStackAfterFatalErrorInDev,
122 resumeActualRenderTimerIfPaused,
123 startBaseRenderTimer,
124 stopBaseRenderTimerIfRunning,
@@ -337,6 +337,12 @@ function resetStack() {
337 if (nextUnitOfWork !== null) {
338 let interruptedWork = nextUnitOfWork.return;
339 while (interruptedWork !== null) {
340 + if (enableProfilerTimer) {
341 + if (interruptedWork.mode & ProfileMode) {
342 + // Resume in case we're picking up on work that was paused.
343 + resumeActualRenderTimerIfPaused(false);
344 + }
345 + }
346 unwindInterruptedWork(interruptedWork);
347 interruptedWork = interruptedWork.return;
348 }
@@ -674,9 +680,13 @@ function commitRoot(root: FiberRoot, finishedWork: Fiber): void {
680
681 if (enableProfilerTimer) {
682 if (__DEV__) {
677 - checkActualRenderTimeStackEmpty();
683 + if (nextRoot === null) {
684 + // Only check this stack once we're done processing async work.
685 + // This prevents a false positive that occurs after a batched commit,
686 + // If there was in-progress async work before the commit.
687 + checkActualRenderTimeStackEmpty();
688 + }
689 }
679 - resetActualRenderTimer();
690 }
691
692 isCommitting = false;
@@ -1100,6 +1110,10 @@ function renderRoot(
1110 // There was a fatal error.
1111 if (__DEV__) {
1112 resetStackAfterFatalErrorInDev();
1113 +
1114 + // Reset the DEV fiber stack in case we're profiling roots.
1115 + // (We do this for profiling bulds when DevTools is detected.)
1116 + resetActualRenderTimerStackAfterFatalErrorInDev();
1117 }
1118 // `nextRoot` points to the in-progress root. A non-null value indicates
1119 // that we're in the middle of an async render. Set it to null to indicate
@@ -1817,7 +1831,7 @@ function performWork(minExpirationTime: ExpirationTime, dl: Deadline | null) {
1831 findHighestPriorityRoot();
1832
1833 if (enableProfilerTimer) {
1820 - resumeActualRenderTimerIfPaused();
1834 + resumeActualRenderTimerIfPaused(minExpirationTime === Sync);
1835 }
1836
1837 if (deadline !== null) {
@@ -1892,7 +1906,7 @@ function flushRoot(root: FiberRoot, expirationTime: ExpirationTime) {
1906 performWorkOnRoot(root, expirationTime, true);
1907 // Flush any sync work that was scheduled by lifecycles
1908 performSyncWork();
1895 - finishRendering();
1909 + pauseActualRenderTimerIfRunning();
1910 }
1911
1912 function finishRendering() {
packages/react-reconciler/src/ReactFiberUnwindWork.js
+1 -6
@@ -51,10 +51,7 @@ import {
51 popTopLevelContextObject as popTopLevelLegacyContextObject,
52 } from './ReactFiberContext';
53 import {popProvider} from './ReactFiberNewContext';
54 -import {
55 - resumeActualRenderTimerIfPaused,
56 - recordElapsedActualRenderTime,
57 -} from './ReactProfilerTimer';
54 +import {recordElapsedActualRenderTime} from './ReactProfilerTimer';
55 import {
56 renderDidSuspend,
57 renderDidError,
@@ -413,8 +410,6 @@ function unwindWork(
410 function unwindInterruptedWork(interruptedWork: Fiber) {
411 if (enableProfilerTimer) {
412 if (interruptedWork.mode & ProfileMode) {
416 - // Resume in case we're picking up on work that was paused.
417 - resumeActualRenderTimerIfPaused();
413 recordElapsedActualRenderTime(interruptedWork);
414 }
415 }
packages/react-reconciler/src/ReactProfilerTimer.js
+23 -9
@@ -21,10 +21,10 @@ export type ProfilerTimer = {
21 markActualRenderTimeStarted(fiber: Fiber): void,
22 pauseActualRenderTimerIfRunning(): void,
23 recordElapsedActualRenderTime(fiber: Fiber): void,
24 - resetActualRenderTimer(): void,
25 - resumeActualRenderTimerIfPaused(): void,
24 + resumeActualRenderTimerIfPaused(isProcessingBatchCommit: boolean): void,
25 recordCommitTime(): void,
26 recordElapsedBaseRenderTimeIfRunning(fiber: Fiber): void,
27 + resetActualRenderTimerStackAfterFatalErrorInDev(): void,
28 startBaseRenderTimer(): void,
29 stopBaseRenderTimerIfRunning(): void,
30 };
@@ -55,6 +55,7 @@ if (__DEV__) {
55 fiberStack = [];
56 }
57
58 +let syncCommitStartTime: number = 0;
59 let timerPausedAt: number = 0;
60 let totalElapsedPauseTime: number = 0;
61
@@ -90,6 +91,14 @@ function pauseActualRenderTimerIfRunning(): void {
91 if (timerPausedAt === 0) {
92 timerPausedAt = now();
93 }
94 + if (syncCommitStartTime > 0) {
95 + // Don't count the time spent processing sycn work,
96 + // Against yielded async work that will be resumed later.
97 + totalElapsedPauseTime += now() - syncCommitStartTime;
98 + syncCommitStartTime = 0;
99 + } else {
100 + totalElapsedPauseTime = 0;
101 + }
102 }
103
104 function recordElapsedActualRenderTime(fiber: Fiber): void {
@@ -108,20 +117,25 @@ function recordElapsedActualRenderTime(fiber: Fiber): void {
117 now() - totalElapsedPauseTime - ((fiber.actualDuration: any): number);
118 }
119
111 -function resetActualRenderTimer(): void {
120 +function resumeActualRenderTimerIfPaused(isProcessingSyncWork: boolean): void {
121 if (!enableProfilerTimer) {
122 return;
123 }
115 - totalElapsedPauseTime = 0;
124 + if (isProcessingSyncWork && syncCommitStartTime === 0) {
125 + syncCommitStartTime = now();
126 + }
127 + if (timerPausedAt > 0) {
128 + totalElapsedPauseTime += now() - timerPausedAt;
129 + timerPausedAt = 0;
130 + }
131 }
132
118 -function resumeActualRenderTimerIfPaused(): void {
133 +function resetActualRenderTimerStackAfterFatalErrorInDev(): void {
134 if (!enableProfilerTimer) {
135 return;
136 }
122 - if (timerPausedAt > 0) {
123 - totalElapsedPauseTime += now() - timerPausedAt;
124 - timerPausedAt = 0;
137 + if (__DEV__) {
138 + fiberStack.length = 0;
139 }
140 }
141
@@ -174,7 +188,7 @@ export {
188 pauseActualRenderTimerIfRunning,
189 recordCommitTime,
190 recordElapsedActualRenderTime,
177 - resetActualRenderTimer,
191 + resetActualRenderTimerStackAfterFatalErrorInDev,
192 resumeActualRenderTimerIfPaused,
193 recordElapsedBaseRenderTimeIfRunning,
194 startBaseRenderTimer,
packages/react-reconciler/src/__tests__/ReactIncrementalErrorHandling-test.internal.js
+1 -1
@@ -1211,7 +1211,7 @@ describe('ReactIncrementalErrorHandling', () => {
1211 });
1212
1213 it('handles error thrown by host config while working on failed root', () => {
1214 - ReactNoop.simulateErrorInHostConfig(() => {
1214 + ReactNoop.simulateErrorInHostConfigDuringBeginPhase(() => {
1215 ReactNoop.render(<span />);
1216 expect(() => ReactNoop.flush()).toThrow('Error in host config.');
1217 });
packages/react-reconciler/src/__tests__/ReactIncrementalErrorReplay-test.js
+1 -10
@@ -20,17 +20,8 @@ describe('ReactIncrementalErrorReplay', () => {
20 ReactNoop = require('react-noop-renderer');
21 });
22
23 - function div(...children) {
24 - children = children.map(c => (typeof c === 'string' ? {text: c} : c));
25 - return {type: 'div', children, prop: undefined};
26 - }
27 -
28 - function span(prop) {
29 - return {type: 'span', children: [], prop};
30 - }
31 -
23 it('should fail gracefully on error in the host environment', () => {
33 - ReactNoop.simulateErrorInHostConfig(() => {
24 + ReactNoop.simulateErrorInHostConfigDuringBeginPhase(() => {
25 ReactNoop.render(<span />);
26 expect(() => ReactNoop.flush()).toThrow('Error in host config.');
27 });
packages/react/src/__tests__/ReactProfiler-test.internal.js
+111 -4
@@ -11,11 +11,13 @@
11
12 let React;
13 let ReactFeatureFlags;
14 +let ReactNoop;
15 let ReactTestRenderer;
16
17 function loadModules({
18 enableProfilerTimer = true,
19 replayFailedUnitOfWorkWithInvokeGuardedCallback = false,
20 + useNoopRenderer = false,
21 } = {}) {
22 ReactFeatureFlags = require('shared/ReactFeatureFlags');
23 ReactFeatureFlags.debugRenderPhaseSideEffects = false;
@@ -24,9 +26,21 @@ function loadModules({
26 ReactFeatureFlags.enableGetDerivedStateFromCatch = true;
27 ReactFeatureFlags.replayFailedUnitOfWorkWithInvokeGuardedCallback = replayFailedUnitOfWorkWithInvokeGuardedCallback;
28 React = require('react');
27 - ReactTestRenderer = require('react-test-renderer');
29 +
30 + if (useNoopRenderer) {
31 + ReactNoop = require('react-noop-renderer');
32 + } else {
33 + ReactTestRenderer = require('react-test-renderer');
34 + }
35 }
36
37 +const mockDevToolsForTest = () => {
38 + jest.mock('react-reconciler/src/ReactFiberDevToolsHook', () => ({
39 + injectInternals: () => {},
40 + isDevToolsPresent: true,
41 + }));
42 +};
43 +
44 describe('Profiler', () => {
45 describe('works in profiling and non-profiling bundles', () => {
46 [true, false].forEach(flagEnabled => {
@@ -174,13 +188,17 @@ describe('Profiler', () => {
188 <AdvanceTime />
189 <AdvanceTime />
190 <AdvanceTime />
191 + <AdvanceTime />
192 + <AdvanceTime />
193 </div>,
194 );
195
180 - // Should be called twice: once to compute the update expiration time,
181 - // and once to record the commit time.
196 + // Should be called two times:
197 + // 1. To mark the start (resuming) of work
198 + // 2. To compute the update expiration time,
199 + // 3. To record the commit time.
200 // No additional calls from ProfilerTimer are expected.
183 - expect(mockNow).toHaveBeenCalledTimes(2);
201 + expect(mockNow).toHaveBeenCalledTimes(3);
202 });
203
204 it('logs render times for both mount and update', () => {
@@ -960,6 +978,35 @@ describe('Profiler', () => {
978 // commit time
979 expect(mountCall[5]).toBe(flagEnabled && __DEV__ ? 54 : 44);
980 });
981 +
982 + it('should reset the fiber stack correct after a "complete" phase error', () => {
983 + jest.resetModules();
984 +
985 + loadModules({
986 + useNoopRenderer: true,
987 + replayFailedUnitOfWorkWithInvokeGuardedCallback: flagEnabled,
988 + });
989 +
990 + // Simulate a renderer error during the "complete" phase.
991 + // This mimics behavior like React Native's View/Text nesting validation.
992 + ReactNoop.simulateErrorInHostConfigDuringCompletePhase(() => {
993 + ReactNoop.render(
994 + <React.unstable_Profiler id="profiler" onRender={jest.fn()}>
995 + <span>hi</span>
996 + </React.unstable_Profiler>,
997 + );
998 + expect(ReactNoop.flush).toThrow('Error in host config.');
999 + });
1000 +
1001 + // So long as the profiler timer's fiber stack is reset correctly,
1002 + // Subsequent renders should not error.
1003 + ReactNoop.render(
1004 + <React.unstable_Profiler id="profiler" onRender={jest.fn()}>
1005 + <span>hi</span>
1006 + </React.unstable_Profiler>,
1007 + );
1008 + ReactNoop.flush();
1009 + });
1010 });
1011 });
1012 });
@@ -1002,4 +1049,64 @@ describe('Profiler', () => {
1049 expect(updateCall[4]).toBe(27); // start time
1050 });
1051 });
1052 +
1053 + it('should handle interleaved async yields and batched commits', () => {
1054 + jest.resetModules();
1055 + mockDevToolsForTest();
1056 + loadModules({useNoopRenderer: true});
1057 +
1058 + const Child = ({duration, id}) => {
1059 + ReactNoop.advanceTime(duration);
1060 + ReactNoop.yield(`Child:render:${id}`);
1061 + return null;
1062 + };
1063 +
1064 + class Parent extends React.Component {
1065 + componentDidMount() {
1066 + ReactNoop.yield(`Parent:componentDidMount:${this.props.id}`);
1067 + }
1068 + render() {
1069 + const {duration, id} = this.props;
1070 + return (
1071 + <React.Fragment>
1072 + <Child duration={duration} id={id} />
1073 + <Child duration={duration} id={id} />
1074 + </React.Fragment>
1075 + );
1076 + }
1077 + }
1078 +
1079 + ReactNoop.advanceTime(50);
1080 +
1081 + ReactNoop.renderToRootWithID(<Parent duration={3} id="one" />, 'one');
1082 +
1083 + // Process up to the <Parent> component, but yield before committing.
1084 + // This ensures that the profiler timer still has paused fibers.
1085 + const commitFirstRender = ReactNoop.flushWithoutCommitting(
1086 + ['Child:render:one', 'Child:render:one'],
1087 + 'one',
1088 + );
1089 +
1090 + expect(ReactNoop.getRoot('one').current.actualDuration).toBe(0);
1091 +
1092 + ReactNoop.advanceTime(100);
1093 +
1094 + // Process some async work, but yield before committing it.
1095 + ReactNoop.renderToRootWithID(<Parent duration={7} id="two" />, 'two');
1096 + ReactNoop.flushThrough(['Child:render:two']);
1097 +
1098 + ReactNoop.advanceTime(150);
1099 +
1100 + // Commit the previously paused, batched work.
1101 + commitFirstRender(['Parent:componentDidMount:one']);
1102 +
1103 + expect(ReactNoop.getRoot('one').current.actualDuration).toBe(6);
1104 + expect(ReactNoop.getRoot('two').current.actualDuration).toBe(0);
1105 +
1106 + ReactNoop.advanceTime(200);
1107 +
1108 + ReactNoop.flush();
1109 +
1110 + expect(ReactNoop.getRoot('two').current.actualDuration).toBe(14);
1111 + });
1112 });
packages/react/src/__tests__/ReactProfilerDevToolsIntegration-test.internal.js
+37
@@ -108,4 +108,41 @@ describe('ReactProfiler DevTools integration', () => {
108 // The updated 6ms for the component that does.
109 expect(rendered.root.findByType(App)._currentFiber().treeBaseTime).toBe(15);
110 });
111 +
112 + it('should reset the fiber stack correctly after an error when profiling host roots', () => {
113 + advanceTimeBy(20);
114 +
115 + const rendered = ReactTestRenderer.create(
116 + <div>
117 + <AdvanceTime byAmount={2} />
118 + </div>,
119 + );
120 +
121 + advanceTimeBy(20);
122 +
123 + expect(() => {
124 + rendered.update(
125 + <div ref="this-will-cause-an-error">
126 + <AdvanceTime byAmount={3} />
127 + </div>,
128 + );
129 + }).toThrow();
130 +
131 + advanceTimeBy(20);
132 +
133 + // But this should render correctly, if the profiler's fiber stack has been reset.
134 + rendered.update(
135 + <div>
136 + <AdvanceTime byAmount={7} />
137 + </div>,
138 + );
139 +
140 + // Measure unobservable timing required by the DevTools profiler.
141 + // At this point, the base time should include only the most recent (not failed) render.
142 + // It should not include time spent on the initial render,
143 + // Or time that elapsed between any of the above renders.
144 + expect(rendered.root.findByType('div')._currentFiber().treeBaseTime).toBe(
145 + 7,
146 + );
147 + });
148 });