From 22f7663f14f12ebd6174292931e94d2b352cf666 Mon Sep 17 00:00:00 2001 From: Brian Vaughn Date: Wed, 20 May 2020 18:36:57 -0700 Subject: [PATCH] Profiler: Don't count timed out (hidden) subtrees in base duration (#18966) --- .../src/ReactFiberWorkLoop.new.js | 14 ++- .../src/ReactFiberWorkLoop.old.js | 14 ++- .../src/__tests__/ReactSuspenseList-test.js | 8 +- .../ReactSuspensePlaceholder-test.internal.js | 28 ++---- .../__tests__/ReactProfiler-test.internal.js | 86 +++++++++++++++++++ 5 files changed, 120 insertions(+), 30 deletions(-) diff --git a/packages/react-reconciler/src/ReactFiberWorkLoop.new.js b/packages/react-reconciler/src/ReactFiberWorkLoop.new.js index fc9a5c828e..0a29277d75 100644 --- a/packages/react-reconciler/src/ReactFiberWorkLoop.new.js +++ b/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 { diff --git a/packages/react-reconciler/src/ReactFiberWorkLoop.old.js b/packages/react-reconciler/src/ReactFiberWorkLoop.old.js index 46bb4df2ef..456bd9670e 100644 --- a/packages/react-reconciler/src/ReactFiberWorkLoop.old.js +++ b/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 { diff --git a/packages/react-reconciler/src/__tests__/ReactSuspenseList-test.js b/packages/react-reconciler/src/__tests__/ReactSuspenseList-test.js index 0388352d1f..c3df69a81b 100644 --- a/packages/react-reconciler/src/__tests__/ReactSuspenseList-test.js +++ b/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(); diff --git a/packages/react-reconciler/src/__tests__/ReactSuspensePlaceholder-test.internal.js b/packages/react-reconciler/src/__tests__/ReactSuspensePlaceholder-test.internal.js index f2ed3c5c39..c28bd711f2 100644 --- a/packages/react-reconciler/src/__tests__/ReactSuspensePlaceholder-test.internal.js +++ b/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( , @@ -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 diff --git a/packages/react/src/__tests__/ReactProfiler-test.internal.js b/packages/react/src/__tests__/ReactProfiler-test.internal.js index 9b1ae8f0f2..63f596f391 100644 --- a/packages/react/src/__tests__/ReactProfiler-test.internal.js +++ b/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
Other
; + } + + function Fallback() { + Scheduler.unstable_advanceTime(8); + Scheduler.unstable_yieldValue('Fallback'); + return
Fallback
; + } + + let shouldSuspend = false; + function Suspender() { + Scheduler.unstable_advanceTime(15); + if (shouldSuspend) { + Scheduler.unstable_yieldValue('Suspender!'); + throw promise; + } + Scheduler.unstable_yieldValue('Suspender'); + return
Suspender
; + } + + function App() { + return ( + + + }> + + + + ); + } + + ReactNoop.render(); + expect(Scheduler).toFlushAndYield(['Other', 'Suspender']); + expect(ReactNoop).toMatchRenderedOutput( + <> +
Other
+
Suspender
+ , + ); + 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(); + expect(Scheduler).toFlushAndYield(['Other', 'Suspender!', 'Fallback']); + await awaitableAdvanceTimers(20000); + expect(ReactNoop).toMatchRenderedOutput( + <> +
Other
+ +
Fallback
+ , + ); + 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( + <> +
Other
+
Suspender
+ , + ); + expect(onRender).toHaveBeenCalledTimes(3); + expect(onRender.mock.calls[2][2]).toBe(15); // actual + expect(onRender.mock.calls[2][3]).toBe(1 + 15); // base + }); }); }); });