From 3ff2c7ccd4d174786aed0f16cc0dd784816ae977 Mon Sep 17 00:00:00 2001 From: Brian Vaughn Date: Wed, 7 Nov 2018 15:46:30 -0800 Subject: [PATCH] Invalid actualDuration+treeBaseDuration for hidden+suspended trees (#14065) * Fixed `treeBaseDuration` by propagating its value from the suspended tree to the Fragment React temporarily wraps around it when showing the fallback UI. * Fixed `actualDuration` by recording elapsed profiler time in the event of an error. * Fixed `actualDuration` in concurrent mode by propagating the time spent rendering the suspending component to its parent. Also updated ReactSuspensePlaceholder-test.internal to cover these new cases. --- .../src/ReactFiberBeginWork.js | 40 ++- .../src/ReactFiberScheduler.js | 30 ++- .../ReactSuspensePlaceholder-test.internal.js | 251 +++++++++++++++++- 3 files changed, 297 insertions(+), 24 deletions(-) diff --git a/packages/react-reconciler/src/ReactFiberBeginWork.js b/packages/react-reconciler/src/ReactFiberBeginWork.js index 7891394377f1f..080f3a1fa8361 100644 --- a/packages/react-reconciler/src/ReactFiberBeginWork.js +++ b/packages/react-reconciler/src/ReactFiberBeginWork.js @@ -66,7 +66,12 @@ import { } from './ReactChildFiber'; import {processUpdateQueue} from './ReactUpdateQueue'; import {NoWork, Never} from './ReactFiberExpirationTime'; -import {ConcurrentMode, StrictMode, NoContext} from './ReactTypeOfMode'; +import { + ConcurrentMode, + NoContext, + ProfileMode, + StrictMode, +} from './ReactTypeOfMode'; import { shouldSetTextContent, shouldDeprioritizeSubtree, @@ -743,7 +748,7 @@ function mountLazyComponent( ) { if (_current !== null) { // An lazy component only mounts if it suspended inside a non- - // concurrent tree, in an inconsistent state. We want to tree it like + // concurrent tree, in an inconsistent state. We want to treat it like // a new mount, even though an empty version of it already committed. // Disconnect the alternate pointers. _current.alternate = null; @@ -829,7 +834,7 @@ function mountIncompleteClassComponent( ) { if (_current !== null) { // An incomplete component only mounts if it suspended inside a non- - // concurrent tree, in an inconsistent state. We want to tree it like + // concurrent tree, in an inconsistent state. We want to treat it like // a new mount, even though an empty version of it already committed. // Disconnect the alternate pointers. _current.alternate = null; @@ -886,7 +891,7 @@ function mountIndeterminateComponent( ) { if (_current !== null) { // An indeterminate component only mounts if it suspended inside a non- - // concurrent tree, in an inconsistent state. We want to tree it like + // concurrent tree, in an inconsistent state. We want to treat it like // a new mount, even though an empty version of it already committed. // Disconnect the alternate pointers. _current.alternate = null; @@ -1188,6 +1193,19 @@ function updateSuspenseComponent( } } + // Because primaryChildFragment is a new fiber that we're inserting as the + // parent of a new tree, we need to set its treeBaseDuration. + if (enableProfilerTimer && workInProgress.mode & ProfileMode) { + // treeBaseDuration is the sum of all the child tree base durations. + let treeBaseDuration = 0; + let hiddenChild = primaryChildFragment.child; + while (hiddenChild !== null) { + treeBaseDuration += hiddenChild.treeBaseDuration; + hiddenChild = hiddenChild.sibling; + } + primaryChildFragment.treeBaseDuration = treeBaseDuration; + } + // Clone the fallback child fragment, too. These we'll continue // working on. const fallbackChildFragment = (primaryChildFragment.sibling = createWorkInProgress( @@ -1239,6 +1257,7 @@ function updateSuspenseComponent( NoWork, null, ); + primaryChildFragment.effectTag |= Placement; primaryChildFragment.child = currentPrimaryChild; currentPrimaryChild.return = primaryChildFragment; @@ -1254,6 +1273,19 @@ function updateSuspenseComponent( primaryChildFragment.child = progressedPrimaryChild; } + // Because primaryChildFragment is a new fiber that we're inserting as the + // parent of a new tree, we need to set its treeBaseDuration. + if (enableProfilerTimer && workInProgress.mode & ProfileMode) { + // treeBaseDuration is the sum of all the child tree base durations. + let treeBaseDuration = 0; + let hiddenChild = primaryChildFragment.child; + while (hiddenChild !== null) { + treeBaseDuration += hiddenChild.treeBaseDuration; + hiddenChild = hiddenChild.sibling; + } + primaryChildFragment.treeBaseDuration = treeBaseDuration; + } + // Create a fragment from the fallback children, too. const fallbackChildFragment = (primaryChildFragment.sibling = createFiberFromFragment( nextFallbackChildren, diff --git a/packages/react-reconciler/src/ReactFiberScheduler.js b/packages/react-reconciler/src/ReactFiberScheduler.js index 46475e7af2964..d06740d25c51c 100644 --- a/packages/react-reconciler/src/ReactFiberScheduler.js +++ b/packages/react-reconciler/src/ReactFiberScheduler.js @@ -1049,9 +1049,18 @@ function completeUnitOfWork(workInProgress: Fiber): Fiber | null { return null; } } else { - if (workInProgress.mode & ProfileMode) { + if (enableProfilerTimer && workInProgress.mode & ProfileMode) { // Record the render duration for the fiber that errored. stopProfilerTimerIfRunningAndRecordDelta(workInProgress, false); + + // Include the time spent working on failed children before continuing. + let actualDuration = workInProgress.actualDuration; + let child = workInProgress.child; + while (child !== null) { + actualDuration += child.actualDuration; + child = child.sibling; + } + workInProgress.actualDuration = actualDuration; } // This fiber did not complete because something threw. Pop values off @@ -1076,19 +1085,6 @@ function completeUnitOfWork(workInProgress: Fiber): Fiber | null { ReactFiberInstrumentation.debugTool.onCompleteWork(workInProgress); } - if (enableProfilerTimer) { - // Include the time spent working on failed children before continuing. - if (next.mode & ProfileMode) { - let actualDuration = next.actualDuration; - let child = next.child; - while (child !== null) { - actualDuration += child.actualDuration; - child = child.sibling; - } - next.actualDuration = actualDuration; - } - } - // If completing this work spawned new work, do that next. We'll come // back here again. // Since we're restarting, remove anything that is not a host effect @@ -1314,6 +1310,12 @@ function renderRoot(root: FiberRoot, isYieldy: boolean): void { didFatal = true; onUncaughtError(thrownValue); } else { + if (enableProfilerTimer && nextUnitOfWork.mode & ProfileMode) { + // Record the time spent rendering before an error was thrown. + // This avoids inaccurate Profiler durations in the case of a suspended render. + stopProfilerTimerIfRunningAndRecordDelta(nextUnitOfWork, true); + } + if (__DEV__) { // Reset global debug state // We assume this is defined in DEV diff --git a/packages/react-reconciler/src/__tests__/ReactSuspensePlaceholder-test.internal.js b/packages/react-reconciler/src/__tests__/ReactSuspensePlaceholder-test.internal.js index 971b73ad9e1d1..cb020732ca2a1 100644 --- a/packages/react-reconciler/src/__tests__/ReactSuspensePlaceholder-test.internal.js +++ b/packages/react-reconciler/src/__tests__/ReactSuspensePlaceholder-test.internal.js @@ -16,6 +16,9 @@ runPlaceholderTests('ReactSuspensePlaceholder (persistence)', () => ); function runPlaceholderTests(suiteLabel, loadReactNoop) { + let advanceTimeBy; + let mockNow; + let Profiler; let React; let ReactTestRenderer; let ReactFeatureFlags; @@ -27,13 +30,24 @@ function runPlaceholderTests(suiteLabel, loadReactNoop) { describe(suiteLabel, () => { beforeEach(() => { jest.resetModules(); + + let currentTime = 0; + mockNow = jest.fn().mockImplementation(() => currentTime); + global.Date.now = mockNow; + advanceTimeBy = amount => { + currentTime += amount; + }; + ReactFeatureFlags = require('shared/ReactFeatureFlags'); ReactFeatureFlags.debugRenderPhaseSideEffectsForStrictMode = false; + ReactFeatureFlags.enableProfilerTimer = true; ReactFeatureFlags.replayFailedUnitOfWorkWithInvokeGuardedCallback = false; React = require('react'); ReactTestRenderer = require('react-test-renderer'); + ReactTestRenderer.unstable_setNowImplementation(mockNow); ReactCache = require('react-cache'); + Profiler = React.unstable_Profiler; Suspense = React.Suspense; TextResource = ReactCache.unstable_createResource(([text, ms = 0]) => { @@ -83,15 +97,16 @@ function runPlaceholderTests(suiteLabel, loadReactNoop) { textResourceShouldFail = false; }); - function Text(props) { - ReactTestRenderer.unstable_yield(props.text); - return props.text; + function Text({fakeRenderDuration = 0, text = 'Text'}) { + advanceTimeBy(fakeRenderDuration); + ReactTestRenderer.unstable_yield(text); + return text; } - function AsyncText(props) { - const text = props.text; + function AsyncText({fakeRenderDuration = 0, ms, text}) { + advanceTimeBy(fakeRenderDuration); try { - TextResource.read([props.text, props.ms]); + TextResource.read([text, ms]); ReactTestRenderer.unstable_yield(text); return text; } catch (promise) { @@ -215,5 +230,229 @@ function runPlaceholderTests(suiteLabel, loadReactNoop) { // given a `hidden` prop. expect(root).toMatchRenderedOutput('AB2C'); }); + + describe('profiler durations', () => { + let App; + let onRender; + + beforeEach(() => { + // Order of parameters: id, phase, actualDuration, treeBaseDuration + onRender = jest.fn(); + + const Fallback = () => { + ReactTestRenderer.unstable_yield('Fallback'); + advanceTimeBy(10); + return 'Loading...'; + }; + + const Suspending = () => { + ReactTestRenderer.unstable_yield('Suspending'); + advanceTimeBy(2); + return ; + }; + + App = ({shouldSuspend, text = 'Text', textRenderDuration = 5}) => { + ReactTestRenderer.unstable_yield('App'); + return ( + + }> + {shouldSuspend && } + + + + ); + }; + }); + + describe('when suspending during mount', () => { + it('properly accounts for base durations when a suspended times out in a sync tree', () => { + const root = ReactTestRenderer.create(); + expect(root.toJSON()).toEqual(['Loading...']); + expect(onRender).toHaveBeenCalledTimes(1); + + // Initial mount only shows the "Loading..." Fallback. + // The treeBaseDuration then should be 10ms spent rendering Fallback, + // but the actualDuration should also include the 8ms spent rendering the hidden tree. + expect(onRender.mock.calls[0][2]).toBe(18); + expect(onRender.mock.calls[0][3]).toBe(10); + + jest.advanceTimersByTime(1000); + + expect(root.toJSON()).toEqual(['Loaded', 'Text']); + expect(onRender).toHaveBeenCalledTimes(2); + + // When the suspending data is resolved and our final UI is rendered, + // the baseDuration should only include the 1ms re-rendering AsyncText, + // but the treeBaseDuration should include the full 8ms spent in the tree. + expect(onRender.mock.calls[1][2]).toBe(1); + expect(onRender.mock.calls[1][3]).toBe(8); + }); + + it('properly accounts for base durations when a suspended times out in a concurrent tree', () => { + const root = ReactTestRenderer.create(, { + unstable_isConcurrent: true, + }); + + expect(root).toFlushAndYield([ + 'App', + 'Suspending', + 'Suspend! [Loaded]', + 'Text', + 'Fallback', + ]); + expect(root).toMatchRenderedOutput(null); + + // Show the fallback UI. + jest.advanceTimersByTime(750); + expect(root).toMatchRenderedOutput('Loading...'); + expect(onRender).toHaveBeenCalledTimes(1); + + // Initial mount only shows the "Loading..." Fallback. + // The treeBaseDuration then should be 10ms spent rendering Fallback, + // but the actualDuration should also include the 8ms spent rendering the hidden tree. + expect(onRender.mock.calls[0][2]).toBe(18); + expect(onRender.mock.calls[0][3]).toBe(10); + + // Resolve the pending promise. + jest.advanceTimersByTime(250); + expect(ReactTestRenderer).toHaveYielded([ + 'Promise resolved [Loaded]', + ]); + expect(root).toFlushAndYield(['Suspending', 'Loaded', 'Text']); + expect(root).toMatchRenderedOutput('LoadedText'); + expect(onRender).toHaveBeenCalledTimes(2); + + // When the suspending data is resolved and our final UI is rendered, + // both times should include the 8ms re-rendering Suspending and AsyncText. + expect(onRender.mock.calls[1][2]).toBe(8); + expect(onRender.mock.calls[1][3]).toBe(8); + }); + }); + + describe('when suspending during update', () => { + it('properly accounts for base durations when a suspended times out in a sync tree', () => { + const root = ReactTestRenderer.create( + , + ); + expect(root.toJSON()).toEqual('Text'); + expect(onRender).toHaveBeenCalledTimes(1); + + // Initial mount only shows the "Text" text. + // It should take 5ms to render. + expect(onRender.mock.calls[0][2]).toBe(5); + expect(onRender.mock.calls[0][3]).toBe(5); + + root.update(); + expect(root.toJSON()).toEqual(['Loading...']); + expect(onRender).toHaveBeenCalledTimes(2); + + // The suspense update should only show the "Loading..." Fallback. + // Both durations should include 10ms spent rendering Fallback + // plus the 8ms rendering the (hidden) components. + expect(onRender.mock.calls[1][2]).toBe(18); + expect(onRender.mock.calls[1][3]).toBe(18); + + root.update( + , + ); + expect(root.toJSON()).toEqual(['Loading...']); + expect(onRender).toHaveBeenCalledTimes(3); + + // If we force another update while still timed out, + // but this time the Text component took 1ms longer to render. + // This should impact both actualDuration and treeBaseDuration. + expect(onRender.mock.calls[2][2]).toBe(19); + expect(onRender.mock.calls[2][3]).toBe(19); + + jest.advanceTimersByTime(1000); + + // TODO Change expected onRender count to 4. + // At the moment, every time we suspended while rendering will cause a commit. + // This will probably change in the future, but that's why there are two new ones. + expect(root.toJSON()).toEqual(['Loaded', 'New']); + expect(onRender).toHaveBeenCalledTimes(5); + + // When the suspending data is resolved and our final UI is rendered, + // the baseDuration should only include the 1ms re-rendering AsyncText, + // but the treeBaseDuration should include the full 9ms spent in the tree. + expect(onRender.mock.calls[3][2]).toBe(1); + expect(onRender.mock.calls[3][3]).toBe(9); + + // TODO Remove these assertions once this commit is gone. + // For now, there was no actual work done during this commit; see above comment. + expect(onRender.mock.calls[4][2]).toBe(0); + expect(onRender.mock.calls[4][3]).toBe(9); + }); + + it('properly accounts for base durations when a suspended times out in a concurrent tree', () => { + const root = ReactTestRenderer.create( + , + { + unstable_isConcurrent: true, + }, + ); + + expect(root).toFlushAndYield(['App', 'Text']); + expect(root).toMatchRenderedOutput('Text'); + expect(onRender).toHaveBeenCalledTimes(1); + + // Initial mount only shows the "Text" text. + // It should take 5ms to render. + expect(onRender.mock.calls[0][2]).toBe(5); + expect(onRender.mock.calls[0][3]).toBe(5); + + root.update(); + expect(root).toFlushAndYield([ + 'App', + 'Suspending', + 'Suspend! [Loaded]', + 'Text', + 'Fallback', + ]); + expect(root).toMatchRenderedOutput('Text'); + + // Show the fallback UI. + jest.advanceTimersByTime(750); + expect(root).toMatchRenderedOutput('Loading...'); + expect(onRender).toHaveBeenCalledTimes(2); + + // The suspense update should only show the "Loading..." Fallback. + // The actual duration should include 10ms spent rendering Fallback, + // plus the 8ms render all of the hidden, suspended subtree. + // But the tree base duration should only include 10ms spent rendering Fallback, + // plus the 5ms rendering the previously committed version of the hidden tree. + expect(onRender.mock.calls[1][2]).toBe(18); + expect(onRender.mock.calls[1][3]).toBe(15); + + // Update again while timed out. + root.update( + , + ); + expect(root).toFlushAndYield([ + 'App', + 'Suspending', + 'Suspend! [Loaded]', + 'New', + 'Fallback', + ]); + expect(root).toMatchRenderedOutput('Loading...'); + expect(onRender).toHaveBeenCalledTimes(2); + + // Resolve the pending promise. + jest.advanceTimersByTime(250); + expect(ReactTestRenderer).toHaveYielded([ + 'Promise resolved [Loaded]', + ]); + expect(root).toFlushAndYield(['App', 'Suspending', 'Loaded', 'New']); + expect(onRender).toHaveBeenCalledTimes(3); + + // When the suspending data is resolved and our final UI is rendered, + // both times should include the 6ms rendering Text, + // the 2ms rendering Suspending, and the 1ms rendering AsyncText. + expect(onRender.mock.calls[2][2]).toBe(9); + expect(onRender.mock.calls[2][3]).toBe(9); + }); + }); + }); }); }