Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Merged
merged 1 commit into from May 21, 2020
Merged

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

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
14 changes: 13 additions & 1 deletion packages/react-reconciler/src/ReactFiberWorkLoop.new.js
View file
Open in desktop
Expand Up @@ -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).
Expand All @@ -1725,6 +1725,18 @@ function resetChildLanes(completedWork: Fiber) {
treeBaseDuration += child.treeBaseDuration;
child = child.sibling;
}

const isTimedOutSuspense =
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Implementation note: I chose to subtract the base duration value after the child loop, rather than doing the check inline, because a single check with a possible subtraction seemed better than a frequent check inside of the child loop. Happy to refactor if there's concern about the approach.

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 {
Expand Down
14 changes: 13 additions & 1 deletion packages/react-reconciler/src/ReactFiberWorkLoop.old.js
View file
Open in desktop
Expand Up @@ -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).
Expand Down Expand Up @@ -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 {
Expand Down
8 changes: 1 addition & 7 deletions packages/react-reconciler/src/__tests__/ReactSuspenseList-test.js
View file
Open in desktop
Expand Up @@ -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();

Expand Down
28 changes: 7 additions & 21 deletions packages/react-reconciler/src/__tests__/ReactSuspensePlaceholder-test.internal.js
View file
Open in desktop
Expand Up @@ -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} />,
Expand All @@ -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);
Expand Down Expand Up @@ -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
Expand Down
86 changes: 86 additions & 0 deletions packages/react/src/__tests__/ReactProfiler-test.internal.js
View file
Open in desktop
Expand Up @@ -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
});
});
});
});