Moved calculation of self duration to the backend/renderer

This enables self duration to be computed accurately despite component filters
This commit is contained in:
Brian Vaughn
2019-05-13 10:13:29 -07:00
parent ffef7ffc57
commit cf99c3ee6c
9 changed files with 342 additions and 115 deletions
@@ -12,6 +12,13 @@ Object {
"commitIndex": 0,
"interactions": Array [],
"rootID": 1,
"selfDurations": Map {
1 => 0,
2 => 10,
3 => 0,
4 => 1,
5 => 1,
},
}
`;
@@ -27,6 +34,13 @@ Object {
"commitIndex": 1,
"interactions": Array [],
"rootID": 1,
"selfDurations": Map {
3 => 0,
4 => 1,
6 => 2,
2 => 10,
1 => 0,
},
}
`;
@@ -40,6 +54,11 @@ Object {
"commitIndex": 2,
"interactions": Array [],
"rootID": 1,
"selfDurations": Map {
3 => 0,
2 => 10,
1 => 0,
},
}
`;
@@ -52,6 +71,10 @@ Object {
"commitIndex": 3,
"interactions": Array [],
"rootID": 1,
"selfDurations": Map {
2 => 10,
1 => 0,
},
}
`;
@@ -59,60 +82,75 @@ exports[`profiling CommitDetails should be collected for each commit: exported d
Object {
"commitDetails": Array [
Object {
"actualDurations": Array [
"commitIndex": 0,
"durations": Array [
1,
12,
0,
2,
12,
10,
3,
0,
0,
4,
1,
1,
5,
1,
1,
],
"commitIndex": 0,
"interactions": Array [],
"rootID": 1,
},
Object {
"actualDurations": Array [
"commitIndex": 1,
"durations": Array [
3,
0,
0,
4,
1,
1,
6,
2,
2,
2,
13,
10,
1,
13,
0,
],
"commitIndex": 1,
"interactions": Array [],
"rootID": 1,
},
Object {
"actualDurations": Array [
"commitIndex": 2,
"durations": Array [
3,
0,
0,
2,
10,
10,
1,
10,
0,
],
"commitIndex": 2,
"interactions": Array [],
"rootID": 1,
},
Object {
"actualDurations": Array [
"commitIndex": 3,
"durations": Array [
2,
10,
10,
1,
10,
0,
],
"commitIndex": 3,
"interactions": Array [],
"rootID": 1,
},
@@ -295,15 +333,71 @@ Object {
}
`;
exports[`profiling CommitDetails should calculate a self duration based on actual children (not filtered children): CommitDetails with filtered self durations 1`] = `
Object {
"actualDurations": Map {
1 => 16,
2 => 16,
3 => 1,
5 => 1,
},
"commitIndex": 0,
"interactions": Array [],
"rootID": 1,
"selfDurations": Map {
1 => 0,
2 => 10,
3 => 1,
5 => 1,
},
}
`;
exports[`profiling CommitDetails should calculate self duration correctly for suspended views: CommitDetails with filtered self durations 1`] = `
Object {
"actualDurations": Map {
1 => 15,
2 => 15,
3 => 5,
4 => 2,
},
"commitIndex": 0,
"interactions": Array [],
"rootID": 1,
"selfDurations": Map {
1 => 0,
2 => 10,
3 => 3,
4 => 2,
},
}
`;
exports[`profiling CommitDetails should calculate self duration correctly for suspended views: CommitDetails with filtered self durations 2`] = `
Object {
"actualDurations": Map {
5 => 3,
3 => 3,
},
"commitIndex": 1,
"interactions": Array [],
"rootID": 1,
"selfDurations": Map {
5 => 3,
3 => 0,
},
}
`;
exports[`profiling FiberCommits should be collected for each rendered fiber: FiberCommits: element 2 1`] = `
Object {
"commitDurations": Array [
0,
11,
10,
1,
11,
10,
2,
13,
10,
],
"fiberID": 2,
"rootID": 1,
@@ -364,49 +458,62 @@ exports[`profiling FiberCommits should be collected for each rendered fiber: exp
Object {
"commitDetails": Array [
Object {
"actualDurations": Array [
"commitIndex": 0,
"durations": Array [
1,
11,
0,
2,
11,
10,
3,
0,
0,
4,
1,
1,
],
"commitIndex": 0,
"interactions": Array [],
"rootID": 1,
},
Object {
"actualDurations": Array [
"commitIndex": 1,
"durations": Array [
3,
0,
0,
5,
1,
1,
2,
11,
10,
1,
11,
0,
],
"commitIndex": 1,
"interactions": Array [],
"rootID": 1,
},
Object {
"actualDurations": Array [
"commitIndex": 2,
"durations": Array [
3,
0,
0,
5,
1,
1,
6,
2,
2,
2,
13,
10,
1,
13,
0,
],
"commitIndex": 2,
"interactions": Array [],
"rootID": 1,
},
@@ -609,17 +716,21 @@ exports[`profiling Interactions should be collected for every traced interaction
Object {
"commitDetails": Array [
Object {
"actualDurations": Array [
"commitIndex": 0,
"durations": Array [
1,
11,
0,
2,
11,
10,
3,
0,
0,
4,
1,
1,
],
"commitIndex": 0,
"interactions": Array [
Object {
"__count": 1,
@@ -631,17 +742,21 @@ Object {
"rootID": 1,
},
Object {
"actualDurations": Array [
"commitIndex": 1,
"durations": Array [
3,
0,
0,
5,
1,
1,
2,
11,
10,
1,
11,
0,
],
"commitIndex": 1,
"interactions": Array [
Object {
"__count": 0,
@@ -833,43 +948,53 @@ exports[`profiling ProfilingSummary should be collected for each commit: exporte
Object {
"commitDetails": Array [
Object {
"actualDurations": Array [
"commitIndex": 0,
"durations": Array [
3,
0,
0,
4,
1,
1,
6,
2,
2,
2,
13,
10,
1,
13,
0,
],
"commitIndex": 0,
"interactions": Array [],
"rootID": 1,
},
Object {
"actualDurations": Array [
"commitIndex": 1,
"durations": Array [
3,
0,
0,
2,
10,
10,
1,
10,
0,
],
"commitIndex": 1,
"interactions": Array [],
"rootID": 1,
},
Object {
"actualDurations": Array [
"commitIndex": 2,
"durations": Array [
2,
10,
10,
1,
10,
0,
],
"commitIndex": 2,
"interactions": Array [],
"rootID": 1,
},
+135
View File
@@ -253,6 +253,141 @@ describe('profiling', () => {
done();
});
it('should calculate a self duration based on actual children (not filtered children)', async done => {
store.componentFilters = [utils.createDisplayNameFilter('^Parent$')];
const Grandparent = () => {
Scheduler.advanceTime(10);
return (
<React.Fragment>
<Parent key="one" />
<Parent key="two" />
</React.Fragment>
);
};
const Parent = () => {
Scheduler.advanceTime(2);
return <Child />;
};
const Child = () => {
Scheduler.advanceTime(1);
return null;
};
utils.act(() => store.startProfiling());
utils.act(() =>
ReactDOM.render(<Grandparent />, document.createElement('div'))
);
utils.act(() => store.stopProfiling());
let commitDetails = null;
function Suspender({ commitIndex, rendererID, rootID }) {
commitDetails = store.profilingCache.CommitDetails.read({
commitIndex,
rendererID,
rootID,
});
expect(commitDetails).toMatchSnapshot(
`CommitDetails with filtered self durations`
);
return null;
}
const rendererID = utils.getRendererID();
const rootID = store.roots[0];
await utils.actAsync(() => {
TestRenderer.create(
<React.Suspense fallback={null}>
<Suspender
commitIndex={0}
rendererID={rendererID}
rootID={rootID}
/>
</React.Suspense>
);
});
expect(commitDetails).not.toBeNull();
done();
});
it('should calculate self duration correctly for suspended views', async done => {
let data;
const getData = () => {
if (data) {
return data;
} else {
throw new Promise(resolve => {
data = 'abc';
resolve(data);
});
}
};
const Parent = () => {
Scheduler.advanceTime(10);
return (
<React.Suspense fallback={<Fallback />}>
<Async />
</React.Suspense>
);
};
const Fallback = () => {
Scheduler.advanceTime(2);
return 'Fallback...';
};
const Async = () => {
Scheduler.advanceTime(3);
const data = getData();
return data;
};
utils.act(() => store.startProfiling());
await utils.actAsync(() =>
ReactDOM.render(<Parent />, document.createElement('div'))
);
utils.act(() => store.stopProfiling());
const allCommitDetails = [];
function Suspender({ commitIndex, rendererID, rootID }) {
const commitDetails = store.profilingCache.CommitDetails.read({
commitIndex,
rendererID,
rootID,
});
allCommitDetails.push(commitDetails);
expect(commitDetails).toMatchSnapshot(
`CommitDetails with filtered self durations`
);
return null;
}
const rendererID = utils.getRendererID();
const rootID = store.roots[0];
for (let commitIndex = 0; commitIndex < 2; commitIndex++) {
await utils.actAsync(() => {
TestRenderer.create(
<React.Suspense fallback={null}>
<Suspender
commitIndex={commitIndex}
rendererID={rendererID}
rootID={rootID}
/>
</React.Suspense>
);
});
}
expect(allCommitDetails).toHaveLength(2);
done();
});
});
describe('FiberCommits', () => {
+33 -41
View File
@@ -787,13 +787,8 @@ export function attach(
const isRoot = fiber.tag === HostRoot;
const id = getFiberID(getPrimaryFiber(fiber));
const isProfilingSupported = fiber.hasOwnProperty('treeBaseDuration');
if (isProfilingSupported) {
idToRootMap.set(id, currentRootID);
idToTreeBaseDurationMap.set(id, fiber.treeBaseDuration || 0);
}
const hasOwnerMetadata = fiber.hasOwnProperty('_debugOwner');
const isProfilingSupported = fiber.hasOwnProperty('treeBaseDuration');
if (isRoot) {
pushOperation(TREE_OPERATION_ADD);
@@ -824,26 +819,10 @@ export function attach(
pushOperation(keyStringID);
}
if (isProfiling) {
// Tree base duration updates are included in the operations typed array.
// So we have to convert them from milliseconds to microseconds so we can send them as ints.
const treeBaseDuration = Math.floor((fiber.treeBaseDuration || 0) * 1000);
if (isProfilingSupported) {
idToRootMap.set(id, currentRootID);
pushOperation(TREE_OPERATION_UPDATE_TREE_BASE_DURATION);
pushOperation(id);
pushOperation(treeBaseDuration);
const { actualDuration } = fiber;
if (actualDuration != null) {
// If profiling is active, store durations for elements that were rendered during the commit.
// We should do this for all fibers on mount, regardless of their actual durations.
const metadata = ((currentCommitProfilingMetadata: any): CommitProfilingData);
metadata.actualDurations.push(id, actualDuration);
metadata.maxActualDuration = Math.max(
metadata.maxActualDuration,
actualDuration
);
}
recordProfilingDurations(fiber);
}
}
@@ -993,7 +972,7 @@ export function attach(
}
}
function recordTreeDuration(fiber: Fiber) {
function recordProfilingDurations(fiber: Fiber) {
const id = getFiberID(getPrimaryFiber(fiber));
const { actualDuration, treeBaseDuration } = fiber;
@@ -1003,8 +982,8 @@ export function attach(
const { alternate } = fiber;
if (
treeBaseDuration !==
(alternate ? alternate.treeBaseDuration : undefined)
alternate == null ||
treeBaseDuration !== alternate.treeBaseDuration
) {
// Tree base duration updates are included in the operations typed array.
// So we have to convert them from milliseconds to microseconds so we can send them as ints.
@@ -1012,18 +991,31 @@ export function attach(
(fiber.treeBaseDuration || 0) * 1000
);
pushOperation(TREE_OPERATION_UPDATE_TREE_BASE_DURATION);
pushOperation(getFiberID(getPrimaryFiber(fiber)));
pushOperation(id);
pushOperation(treeBaseDuration);
}
if (alternate ? hasDataChanged(alternate, fiber) : true) {
if (alternate == null || hasDataChanged(alternate, fiber)) {
if (actualDuration != null) {
// The actual duration reported by React includes time spent working on children.
// This is useful information, but it's also useful to be able to exclude child durations.
// The frontend can't compute this, since the immediate children may have been filtered out.
// So we need to do this on the backend.
// Note that this calculated self duration is not the same thing as the base duration.
// The two are calculated differently (tree duration does not accumulate).
let selfDuration = actualDuration;
let child = fiber.child;
while (child !== null) {
selfDuration -= child.actualDuration || 0;
child = child.sibling;
}
// If profiling is active, store durations for elements that were rendered during the commit.
// Note that we should do this for any fiber we performed work on, regardless of its actualDuration value.
// In some cases actualDuration might be 0 for fibers we worked on (particularly if we're using Date.now)
// In other cases (e.g. Memo) actualDuration might be greater than 0 even if we "bailed out".
const metadata = ((currentCommitProfilingMetadata: any): CommitProfilingData);
metadata.actualDurations.push(id, actualDuration);
metadata.durations.push(id, actualDuration, selfDuration);
metadata.maxActualDuration = Math.max(
metadata.maxActualDuration,
actualDuration
@@ -1205,7 +1197,7 @@ export function attach(
if (shouldIncludeInTree) {
const isProfilingSupported = nextFiber.hasOwnProperty('treeBaseDuration');
if (isProfilingSupported) {
recordTreeDuration(nextFiber);
recordProfilingDurations(nextFiber);
}
}
if (shouldResetChildren) {
@@ -1267,7 +1259,7 @@ export function attach(
// If profiling is active, store commit time and duration, and the current interactions.
// The frontend may request this information after profiling has stopped.
currentCommitProfilingMetadata = {
actualDurations: [],
durations: [],
commitTime: performance.now() - profilingStartTime,
interactions: Array.from(root.memoizedInteractions).map(
(interaction: InteractionBackend) => ({
@@ -1309,7 +1301,7 @@ export function attach(
// If profiling is active, store commit time and duration, and the current interactions.
// The frontend may request this information after profiling has stopped.
currentCommitProfilingMetadata = {
actualDurations: [],
durations: [],
commitTime: performance.now() - profilingStartTime,
interactions: Array.from(root.memoizedInteractions).map(
(interaction: InteractionBackend) => ({
@@ -1960,8 +1952,8 @@ export function attach(
}
type CommitProfilingData = {|
actualDurations: Array<number>,
commitTime: number,
durations: Array<number>,
interactions: Array<InteractionBackend>,
maxActualDuration: number,
|};
@@ -1987,8 +1979,8 @@ export function attach(
if (commitProfilingData != null) {
return {
commitIndex,
durations: commitProfilingData.durations,
interactions: commitProfilingData.interactions,
actualDurations: commitProfilingData.actualDurations,
rootID,
};
}
@@ -2001,7 +1993,7 @@ export function attach(
return {
commitIndex,
interactions: [],
actualDurations: [],
durations: [],
rootID,
};
}
@@ -2015,10 +2007,10 @@ export function attach(
);
if (commitProfilingMetadata != null) {
const commitDurations = [];
commitProfilingMetadata.forEach(({ actualDurations }, commitIndex) => {
for (let i = 0; i < actualDurations.length; i += 2) {
if (actualDurations[i] === fiberID) {
commitDurations.push(commitIndex, actualDurations[i + 1]);
commitProfilingMetadata.forEach(({ durations }, commitIndex) => {
for (let i = 0; i < durations.length; i += 3) {
if (durations[i] === fiberID) {
commitDurations.push(commitIndex, durations[i + 2]);
break;
}
}
+2 -1
View File
@@ -122,8 +122,9 @@ export type InteractionBackend = {|
|};
export type CommitDetailsBackend = {|
actualDurations: Array<number>,
commitIndex: number,
// Tuple of id, actual duration, and (computed) self duration
durations: Array<number>,
interactions: Array<InteractionBackend>,
rootID: number,
|};
+12 -7
View File
@@ -127,6 +127,7 @@ export default class ProfilingCache {
rootID,
commitIndex,
actualDurations: new Map(),
selfDurations: new Map(),
interactions: [],
});
});
@@ -147,10 +148,10 @@ export default class ProfilingCache {
const { commitDetails } = (importedProfilingData: any);
if (commitDetails != null) {
const commitDurations = [];
commitDetails.forEach(({ actualDurations }, commitIndex) => {
for (let i = 0; i < actualDurations.length; i += 2) {
if (actualDurations[i] === fiberID) {
commitDurations.push(commitIndex, actualDurations[i + 1]);
commitDetails.forEach(({ durations }, commitIndex) => {
for (let i = 0; i < durations.length; i += 3) {
if (durations[i] === fiberID) {
commitDurations.push(commitIndex, durations[i + 2]);
break;
}
}
@@ -332,7 +333,7 @@ export default class ProfilingCache {
onCommitDetails = ({
commitIndex,
actualDurations,
durations,
interactions,
rootID,
}: CommitDetailsBackend) => {
@@ -342,14 +343,18 @@ export default class ProfilingCache {
this._pendingCommitDetailsMap.delete(key);
const actualDurationsMap = new Map();
for (let i = 0; i < actualDurations.length; i += 2) {
actualDurationsMap.set(actualDurations[i], actualDurations[i + 1]);
const selfDurationsMap = new Map();
for (let i = 0; i < durations.length; i += 3) {
const id = durations[i];
actualDurationsMap.set(id, durations[i + 1]);
selfDurationsMap.set(id, durations[i + 2]);
}
resolve({
rootID,
commitIndex,
actualDurations: actualDurationsMap,
selfDurations: selfDurationsMap,
interactions,
});
}
@@ -1,6 +1,6 @@
// @flow
import { calculateSelfDuration, formatDuration } from './utils';
import { formatDuration } from './utils';
import type { CommitDetailsFrontend, CommitTreeFrontend } from './types';
@@ -34,7 +34,7 @@ export function getChartData({
commitIndex: number,
commitTree: CommitTreeFrontend,
|}): ChartData {
const { actualDurations, rootID } = commitDetails;
const { actualDurations, rootID, selfDurations } = commitDetails;
const { nodes } = commitTree;
const key = `${rootID}-${commitIndex}`;
@@ -60,7 +60,7 @@ export function getChartData({
const { children, displayName, key, treeBaseDuration } = node;
const actualDuration = actualDurations.get(id) || 0;
const selfDuration = calculateSelfDuration(id, commitTree, commitDetails);
const selfDuration = selfDurations.get(id) || 0;
const didRender = actualDurations.has(id);
const name = displayName || 'Unknown';
@@ -1,6 +1,6 @@
// @flow
import { calculateSelfDuration, formatDuration } from './utils';
import { formatDuration } from './utils';
import type { CommitDetailsFrontend, CommitTreeFrontend } from './types';
@@ -27,7 +27,7 @@ export function getChartData({
commitIndex: number,
commitTree: CommitTreeFrontend,
|}): ChartData {
const { actualDurations, rootID } = commitDetails;
const { actualDurations, rootID, selfDurations } = commitDetails;
const { nodes } = commitTree;
const key = `${rootID}-${commitIndex}`;
@@ -49,7 +49,7 @@ export function getChartData({
if (node.parentID === 0) {
return;
}
const selfDuration = calculateSelfDuration(id, commitTree, commitDetails);
const selfDuration = selfDurations.get(id) || 0;
maxSelfDuration = Math.max(maxSelfDuration, selfDuration);
const name = node.displayName || 'Unknown';
+1
View File
@@ -31,6 +31,7 @@ export type CommitDetailsFrontend = {|
rootID: number,
commitIndex: number,
actualDurations: Map<number, number>,
selfDurations: Map<number, number>,
interactions: Array<InteractionFrontend>,
|};
+1 -33
View File
@@ -2,11 +2,7 @@
import { PROFILER_EXPORT_VERSION } from 'src/constants';
import type {
CommitDetailsFrontend,
CommitTreeFrontend,
ProfilingSnapshotNode,
} from './types';
import type { ProfilingSnapshotNode } from './types';
const commitGradient = [
'var(--color-commit-gradient-0)',
@@ -21,34 +17,6 @@ const commitGradient = [
'var(--color-commit-gradient-9)',
];
export const calculateSelfDuration = (
id: number,
commitTree: CommitTreeFrontend,
commitDetails: CommitDetailsFrontend
): number => {
const { actualDurations } = commitDetails;
const { nodes } = commitTree;
if (!actualDurations.has(id)) {
return 0;
}
const node = nodes.get(id);
if (node == null) {
throw Error(`Could not find node with id "${id}" in commit tree`);
}
let selfDuration = actualDurations.get(id) || 0;
node.children.forEach(childID => {
if (actualDurations.has(childID)) {
selfDuration -= actualDurations.get(childID) || 0;
}
});
return selfDuration;
};
export const prepareProfilingExport = (
profilingOperations: Map<number, Array<Uint32Array>>,
profilingSnapshots: Map<number, Map<number, ProfilingSnapshotNode>>,