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.

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,

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

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 <AsyncText ms={1000} text="Loaded" fakeRenderDuration={1} />;
+        };
+
+        App = ({shouldSuspend, text = 'Text', textRenderDuration = 5}) => {
+          ReactTestRenderer.unstable_yield('App');
+          return (
+            <Profiler id="root" onRender={onRender}>
+              <Suspense maxDuration={500} fallback={<Fallback />}>
+                {shouldSuspend && <Suspending />}
+                <Text fakeRenderDuration={textRenderDuration} text={text} />
+              </Suspense>
+            </Profiler>
+          );
+        };
+      });
+
+      describe('when suspending during mount', () => {
+        it('properly accounts for base durations when a suspended times out in a sync tree', () => {
+          const root = ReactTestRenderer.create(<App shouldSuspend={true} />);
+          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(<App shouldSuspend={true} />, {
+            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(
+            <App shouldSuspend={false} textRenderDuration={5} />,
+          );
+          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(<App shouldSuspend={true} textRenderDuration={5} />);
+          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(
+            <App shouldSuspend={true} text="New" textRenderDuration={6} />,
+          );
+          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(
+            <App shouldSuspend={false} textRenderDuration={5} />,
+            {
+              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(<App shouldSuspend={true} textRenderDuration={5} />);
+          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(
+            <App shouldSuspend={true} text="New" textRenderDuration={6} />,
+          );
+          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);
+        });
+      });
+    });
   });
 }