Profiler: Don't count timed out (hidden) subtrees in base duration (facebook#18966)

Author: Brian Vaughn

packages/react-reconciler/src/ReactFiberWorkLoop.new.js

@@ -1700,7 +1700,7 @@ function resetChildLanes(completedWork: Fiber) {
     // In profiling mode, resetChildExpirationTime is also used to reset
     // profiler durations.
     let actualDuration = completedWork.actualDuration;
-    let treeBaseDuration = completedWork.selfBaseDuration;
+    let treeBaseDuration = ((completedWork.selfBaseDuration: any): number);
 
     // When a fiber is cloned, its actualDuration is reset to 0. This value will
     // only be updated if work is done on the fiber (i.e. it doesn't bailout).
@@ -1725,6 +1725,18 @@ function resetChildLanes(completedWork: Fiber) {
       treeBaseDuration += child.treeBaseDuration;
       child = child.sibling;
     }
+
+    const isTimedOutSuspense =
+      completedWork.tag === SuspenseComponent &&
+      completedWork.memoizedState !== null;
+    if (isTimedOutSuspense) {
+      // Don't count time spent in a timed out Suspense subtree as part of the base duration.
+      const primaryChildFragment = completedWork.child;
+      if (primaryChildFragment !== null) {
+        treeBaseDuration -= ((primaryChildFragment.treeBaseDuration: any): number);
+      }
+    }
+
     completedWork.actualDuration = actualDuration;
     completedWork.treeBaseDuration = treeBaseDuration;
   } else {

packages/react-reconciler/src/ReactFiberWorkLoop.old.js

@@ -1775,7 +1775,7 @@ function resetChildExpirationTime(completedWork: Fiber) {
     // In profiling mode, resetChildExpirationTime is also used to reset
     // profiler durations.
     let actualDuration = completedWork.actualDuration;
-    let treeBaseDuration = completedWork.selfBaseDuration;
+    let treeBaseDuration = ((completedWork.selfBaseDuration: any): number);
 
     // When a fiber is cloned, its actualDuration is reset to 0. This value will
     // only be updated if work is done on the fiber (i.e. it doesn't bailout).
@@ -1804,6 +1804,18 @@ function resetChildExpirationTime(completedWork: Fiber) {
       treeBaseDuration += child.treeBaseDuration;
       child = child.sibling;
     }
+
+    const isTimedOutSuspense =
+      completedWork.tag === SuspenseComponent &&
+      completedWork.memoizedState !== null;
+    if (isTimedOutSuspense) {
+      // Don't count time spent in a timed out Suspense subtree as part of the base duration.
+      const primaryChildFragment = completedWork.child;
+      if (primaryChildFragment !== null) {
+        treeBaseDuration -= ((primaryChildFragment.treeBaseDuration: any): number);
+      }
+    }
+
     completedWork.actualDuration = actualDuration;
     completedWork.treeBaseDuration = treeBaseDuration;
   } else {

packages/react-reconciler/src/__tests__/ReactSuspenseList-test.js

@@ -2709,13 +2709,7 @@ describe('ReactSuspenseList', () => {
     // actualDuration
     expect(onRender.mock.calls[2][2]).toBe((1 + 4 + 5 + 3) * 2 + 3);
     // treeBaseDuration
-    expect(onRender.mock.calls[2][3]).toBe(
-      1 +
-        4 +
-        3 +
-        3 +
-        /* Resuspending a boundary also includes the content in base duration but it shouldn't */ 5,
-    );
+    expect(onRender.mock.calls[2][3]).toBe(1 + 4 + 3 + 3);
 
     await C.resolve();
 

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

@@ -405,19 +405,9 @@ describe('ReactSuspensePlaceholder', () => {
         // 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.
-        // Note from Andrew to Brian: I don't fully understand why this one
-        // diverges, but I checked and it matches the times we get when
-        // we run this same test in Concurrent Mode.
-        if (gate(flags => flags.new)) {
-          // 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);
-        } else {
-          // Old behavior includes the time spent on the primary tree.
-          expect(onRender.mock.calls[1][2]).toBe(18);
-          expect(onRender.mock.calls[1][3]).toBe(18);
-        }
+        // But the tree base duration should only include 10ms spent rendering Fallback,
+        expect(onRender.mock.calls[1][2]).toBe(18);
+        expect(onRender.mock.calls[1][3]).toBe(10);
 
         ReactNoop.renderLegacySyncRoot(
           <App shouldSuspend={true} text="New" textRenderDuration={6} />,
@@ -432,18 +422,15 @@ describe('ReactSuspensePlaceholder', () => {
         expect(ReactNoop).toMatchRenderedOutput('Loading...');
         expect(onRender).toHaveBeenCalledTimes(3);
 
-        // Note from Andrew to Brian: I don't fully understand why this one
-        // diverges, but I checked and it matches the times we get when
-        // we run this same test in Concurrent Mode.
         if (gate(flags => flags.new)) {
           expect(onRender.mock.calls[1][2]).toBe(18);
-          expect(onRender.mock.calls[1][3]).toBe(15);
+          expect(onRender.mock.calls[1][3]).toBe(10);
         } else {
           // 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);
+          expect(onRender.mock.calls[2][3]).toBe(10);
         }
 
         jest.advanceTimersByTime(1000);
@@ -500,10 +487,9 @@ describe('ReactSuspensePlaceholder', () => {
         // 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.
+        // But the tree base duration should only include 10ms spent rendering Fallback.
         expect(onRender.mock.calls[1][2]).toBe(18);
-        expect(onRender.mock.calls[1][3]).toBe(15);
+        expect(onRender.mock.calls[1][3]).toBe(10);
 
         // Update again while timed out.
         // Since this test was originally written we added an optimization to avoid

packages/react/src/__tests__/ReactProfiler-test.internal.js

@@ -4145,6 +4145,92 @@ describe('Profiler', () => {
         expect(call[0]).toEqual('test-profiler');
         expect(call[4]).toMatchInteractions([]);
       });
+
+      it('should properly report base duration wrt suspended subtrees', async () => {
+        loadModulesForTracing({useNoopRenderer: true});
+
+        const onRender = jest.fn();
+
+        let resolve = null;
+        const promise = new Promise(_resolve => {
+          resolve = _resolve;
+        });
+
+        function Other() {
+          Scheduler.unstable_advanceTime(1);
+          Scheduler.unstable_yieldValue('Other');
+          return <div>Other</div>;
+        }
+
+        function Fallback() {
+          Scheduler.unstable_advanceTime(8);
+          Scheduler.unstable_yieldValue('Fallback');
+          return <div>Fallback</div>;
+        }
+
+        let shouldSuspend = false;
+        function Suspender() {
+          Scheduler.unstable_advanceTime(15);
+          if (shouldSuspend) {
+            Scheduler.unstable_yieldValue('Suspender!');
+            throw promise;
+          }
+          Scheduler.unstable_yieldValue('Suspender');
+          return <div>Suspender</div>;
+        }
+
+        function App() {
+          return (
+            <React.Profiler id="root" onRender={onRender}>
+              <Other />
+              <React.Suspense fallback={<Fallback />}>
+                <Suspender />
+              </React.Suspense>
+            </React.Profiler>
+          );
+        }
+
+        ReactNoop.render(<App />);
+        expect(Scheduler).toFlushAndYield(['Other', 'Suspender']);
+        expect(ReactNoop).toMatchRenderedOutput(
+          <>
+            <div>Other</div>
+            <div>Suspender</div>
+          </>,
+        );
+        expect(onRender).toHaveBeenCalledTimes(1);
+        expect(onRender.mock.calls[0][2]).toBe(1 + 15); // actual
+        expect(onRender.mock.calls[0][3]).toBe(1 + 15); // base
+
+        shouldSuspend = true;
+        ReactNoop.render(<App />);
+        expect(Scheduler).toFlushAndYield(['Other', 'Suspender!', 'Fallback']);
+        await awaitableAdvanceTimers(20000);
+        expect(ReactNoop).toMatchRenderedOutput(
+          <>
+            <div>Other</div>
+            <div hidden={true}>Suspender</div>
+            <div>Fallback</div>
+          </>,
+        );
+        expect(onRender).toHaveBeenCalledTimes(2);
+        expect(onRender.mock.calls[1][2]).toBe(1 + 15 + 8); // actual
+        expect(onRender.mock.calls[1][3]).toBe(1 + 8); // base
+
+        shouldSuspend = false;
+        resolve();
+        await promise;
+        expect(Scheduler).toFlushAndYield(['Suspender']);
+        expect(ReactNoop).toMatchRenderedOutput(
+          <>
+            <div>Other</div>
+            <div>Suspender</div>
+          </>,
+        );
+        expect(onRender).toHaveBeenCalledTimes(3);
+        expect(onRender.mock.calls[2][2]).toBe(15); // actual
+        expect(onRender.mock.calls[2][3]).toBe(1 + 15); // base
+      });
     });
   });
 });