Fixed a Profiler memoization bug and improved test coverage

This commit is contained in:
Brian Vaughn
2019-05-08 15:41:57 -07:00
parent d42f86bb50
commit ee099124e2
4 changed files with 326 additions and 201 deletions
+264 -167
View File
@@ -3,10 +3,11 @@
exports[`profiling CommitDetails should be collected for each commit: CommitDetails commitIndex: 0 1`] = `
Object {
"actualDurations": Map {
1 => 14,
2 => 14,
3 => 2,
4 => 2,
1 => 12,
2 => 12,
3 => 0,
4 => 1,
5 => 1,
},
"commitIndex": 0,
"interactions": Array [],
@@ -17,11 +18,11 @@ Object {
exports[`profiling CommitDetails should be collected for each commit: CommitDetails commitIndex: 1 1`] = `
Object {
"actualDurations": Map {
3 => 2,
4 => 2,
5 => 2,
2 => 16,
1 => 16,
3 => 0,
4 => 1,
6 => 2,
2 => 13,
1 => 13,
},
"commitIndex": 1,
"interactions": Array [],
@@ -32,9 +33,9 @@ Object {
exports[`profiling CommitDetails should be collected for each commit: CommitDetails commitIndex: 2 1`] = `
Object {
"actualDurations": Map {
3 => 2,
2 => 12,
1 => 12,
3 => 0,
2 => 10,
1 => 10,
},
"commitIndex": 2,
"interactions": Array [],
@@ -60,13 +61,15 @@ Object {
Object {
"actualDurations": Array [
1,
14,
12,
2,
14,
12,
3,
2,
0,
4,
2,
1,
5,
1,
],
"commitIndex": 0,
"interactions": Array [],
@@ -75,15 +78,15 @@ Object {
Object {
"actualDurations": Array [
3,
2,
0,
4,
2,
5,
2,
2,
16,
1,
16,
6,
2,
2,
13,
1,
13,
],
"commitIndex": 1,
"interactions": Array [],
@@ -92,11 +95,11 @@ Object {
Object {
"actualDurations": Array [
3,
0,
2,
2,
12,
10,
1,
12,
10,
],
"commitIndex": 2,
"interactions": Array [],
@@ -123,7 +126,7 @@ Object {
Array [
1,
1,
17,
29,
6,
80,
97,
@@ -141,6 +144,18 @@ Object {
48,
1,
49,
11,
77,
101,
109,
111,
40,
67,
104,
105,
108,
100,
41,
1,
1,
11,
@@ -148,7 +163,7 @@ Object {
1,
4,
1,
14000,
12000,
1,
2,
5,
@@ -158,7 +173,7 @@ Object {
0,
4,
2,
14000,
12000,
1,
3,
5,
@@ -168,7 +183,7 @@ Object {
3,
4,
3,
2000,
0,
1,
4,
5,
@@ -178,7 +193,17 @@ Object {
4,
4,
4,
2000,
1000,
1,
5,
8,
2,
2,
5,
0,
4,
5,
1000,
],
Array [
1,
@@ -193,27 +218,28 @@ Object {
1,
50,
1,
5,
6,
5,
2,
2,
1,
2,
4,
5,
6,
2000,
4,
2,
16000,
14000,
3,
2,
3,
4,
3,
4,
6,
5,
4,
1,
16000,
14000,
],
Array [
1,
@@ -221,14 +247,19 @@ Object {
0,
2,
2,
5,
6,
4,
4,
2,
12000,
11000,
3,
2,
2,
3,
5,
4,
1,
12000,
11000,
],
Array [
1,
@@ -237,12 +268,6 @@ Object {
2,
1,
3,
4,
2,
10000,
4,
1,
10000,
],
],
},
@@ -251,16 +276,16 @@ Object {
},
"profilingSummary": Object {
"commitDurations": Array [
14,
16,
12,
13,
10,
10,
],
"commitTimes": Array [
14,
30,
42,
52,
12,
25,
35,
45,
],
"initialTreeBaseDurations": Array [],
"interactionCount": 0,
@@ -274,11 +299,11 @@ exports[`profiling FiberCommits should be collected for each rendered fiber: Fib
Object {
"commitDurations": Array [
0,
12,
11,
1,
14,
11,
2,
16,
13,
],
"fiberID": 2,
"rootID": 1,
@@ -289,11 +314,11 @@ exports[`profiling FiberCommits should be collected for each rendered fiber: Fib
Object {
"commitDurations": Array [
0,
2,
0,
1,
0,
2,
2,
2,
0,
],
"fiberID": 3,
"rootID": 1,
@@ -303,10 +328,8 @@ Object {
exports[`profiling FiberCommits should be collected for each rendered fiber: FiberCommits: element 4 1`] = `
Object {
"commitDurations": Array [
0,
1,
2,
2,
2,
],
"fiberID": 4,
"rootID": 1,
@@ -314,12 +337,25 @@ Object {
`;
exports[`profiling FiberCommits should be collected for each rendered fiber: FiberCommits: element 5 1`] = `
Object {
"commitDurations": Array [
1,
1,
2,
1,
],
"fiberID": 5,
"rootID": 1,
}
`;
exports[`profiling FiberCommits should be collected for each rendered fiber: FiberCommits: element 6 1`] = `
Object {
"commitDurations": Array [
2,
2,
],
"fiberID": 5,
"fiberID": 6,
"rootID": 1,
}
`;
@@ -330,11 +366,13 @@ Object {
Object {
"actualDurations": Array [
1,
12,
11,
2,
12,
11,
3,
2,
0,
4,
1,
],
"commitIndex": 0,
"interactions": Array [],
@@ -343,13 +381,13 @@ Object {
Object {
"actualDurations": Array [
3,
2,
4,
2,
2,
14,
0,
5,
1,
14,
2,
11,
1,
11,
],
"commitIndex": 1,
"interactions": Array [],
@@ -358,15 +396,15 @@ Object {
Object {
"actualDurations": Array [
3,
2,
4,
2,
0,
5,
2,
2,
16,
1,
16,
6,
2,
2,
13,
1,
13,
],
"commitIndex": 2,
"interactions": Array [],
@@ -382,7 +420,7 @@ Object {
Array [
1,
1,
15,
27,
6,
80,
97,
@@ -398,6 +436,18 @@ Object {
100,
1,
48,
11,
77,
101,
109,
111,
40,
67,
104,
105,
108,
100,
41,
1,
1,
11,
@@ -405,7 +455,7 @@ Object {
1,
4,
1,
12000,
11000,
1,
2,
5,
@@ -415,7 +465,7 @@ Object {
0,
4,
2,
12000,
11000,
1,
3,
5,
@@ -425,7 +475,17 @@ Object {
3,
4,
3,
2000,
0,
1,
4,
8,
2,
2,
4,
0,
4,
4,
1000,
],
Array [
1,
@@ -440,26 +500,27 @@ Object {
1,
49,
1,
4,
5,
5,
2,
2,
1,
2,
4,
4,
2000,
5,
1000,
4,
2,
14000,
12000,
3,
2,
2,
3,
3,
5,
4,
4,
1,
14000,
12000,
],
Array [
1,
@@ -474,27 +535,28 @@ Object {
1,
50,
1,
5,
6,
5,
2,
2,
1,
2,
4,
5,
6,
2000,
4,
2,
16000,
14000,
3,
2,
3,
3,
4,
3,
5,
6,
4,
4,
1,
16000,
14000,
],
],
},
@@ -503,14 +565,14 @@ Object {
},
"profilingSummary": Object {
"commitDurations": Array [
12,
14,
16,
11,
11,
13,
],
"commitTimes": Array [
12,
26,
42,
11,
22,
35,
],
"initialTreeBaseDurations": Array [],
"interactionCount": 0,
@@ -538,7 +600,7 @@ Array [
],
"id": 1,
"name": "update: two children",
"timestamp": 12,
"timestamp": 11,
},
]
`;
@@ -549,11 +611,13 @@ Object {
Object {
"actualDurations": Array [
1,
12,
11,
2,
12,
11,
3,
2,
0,
4,
1,
],
"commitIndex": 0,
"interactions": Array [
@@ -569,13 +633,13 @@ Object {
Object {
"actualDurations": Array [
3,
2,
4,
2,
2,
14,
0,
5,
1,
14,
2,
11,
1,
11,
],
"commitIndex": 1,
"interactions": Array [
@@ -583,7 +647,7 @@ Object {
"__count": 0,
"id": 1,
"name": "update: two children",
"timestamp": 12,
"timestamp": 11,
},
],
"rootID": 1,
@@ -607,7 +671,7 @@ Object {
],
"id": 1,
"name": "update: two children",
"timestamp": 12,
"timestamp": 11,
},
],
"rootID": 1,
@@ -617,7 +681,7 @@ Object {
Array [
1,
1,
15,
27,
6,
80,
97,
@@ -633,6 +697,18 @@ Object {
100,
1,
48,
11,
77,
101,
109,
111,
40,
67,
104,
105,
108,
100,
41,
1,
1,
11,
@@ -640,7 +716,7 @@ Object {
1,
4,
1,
12000,
11000,
1,
2,
5,
@@ -650,7 +726,7 @@ Object {
0,
4,
2,
12000,
11000,
1,
3,
5,
@@ -660,7 +736,17 @@ Object {
3,
4,
3,
2000,
0,
1,
4,
8,
2,
2,
4,
0,
4,
4,
1000,
],
Array [
1,
@@ -675,26 +761,27 @@ Object {
1,
49,
1,
4,
5,
5,
2,
2,
1,
2,
4,
4,
2000,
5,
1000,
4,
2,
14000,
12000,
3,
2,
2,
3,
3,
5,
4,
4,
1,
14000,
12000,
],
],
},
@@ -703,12 +790,12 @@ Object {
},
"profilingSummary": Object {
"commitDurations": Array [
12,
14,
11,
11,
],
"commitTimes": Array [
12,
26,
11,
22,
],
"initialTreeBaseDurations": Array [],
"interactionCount": 2,
@@ -721,20 +808,21 @@ Object {
exports[`profiling ProfilingSummary should be collected for each commit: ProfilingSummary 1`] = `
Object {
"commitDurations": Array [
16,
12,
13,
10,
10,
],
"commitTimes": Array [
16,
28,
38,
13,
23,
33,
],
"initialTreeBaseDurations": Map {
1 => 14,
2 => 14,
3 => 2,
4 => 2,
1 => 12,
2 => 12,
3 => 0,
4 => 1,
5 => 1,
},
"interactionCount": 0,
"rootID": 1,
@@ -747,15 +835,15 @@ Object {
Object {
"actualDurations": Array [
3,
2,
0,
4,
2,
5,
2,
2,
16,
1,
16,
6,
2,
2,
13,
1,
13,
],
"commitIndex": 0,
"interactions": Array [],
@@ -764,11 +852,11 @@ Object {
Object {
"actualDurations": Array [
3,
0,
2,
2,
12,
10,
1,
12,
10,
],
"commitIndex": 1,
"interactions": Array [],
@@ -805,27 +893,28 @@ Object {
1,
50,
1,
5,
6,
5,
2,
2,
1,
2,
4,
5,
6,
2000,
4,
2,
16000,
14000,
3,
2,
3,
4,
3,
4,
6,
5,
4,
1,
16000,
14000,
],
Array [
1,
@@ -833,14 +922,19 @@ Object {
0,
2,
2,
5,
6,
4,
4,
2,
12000,
11000,
3,
2,
2,
3,
5,
4,
1,
12000,
11000,
],
Array [
1,
@@ -849,12 +943,6 @@ Object {
2,
1,
3,
4,
2,
10000,
4,
1,
10000,
],
],
},
@@ -872,6 +960,7 @@ Object {
"children": Array [
3,
4,
5,
],
"displayName": "Parent",
"id": 2,
@@ -889,28 +978,36 @@ Object {
"id": 4,
"key": "1",
},
5 => Object {
"children": Array [],
"displayName": "Memo(Child)",
"id": 5,
"key": null,
},
},
},
"profilingSummary": Object {
"commitDurations": Array [
16,
12,
13,
10,
10,
],
"commitTimes": Array [
16,
28,
38,
13,
23,
33,
],
"initialTreeBaseDurations": Array [
1,
14,
12,
2,
14,
12,
3,
2,
0,
4,
2,
1,
5,
1,
],
"interactionCount": 0,
"rootID": 1,
@@ -81,9 +81,9 @@ Object {
Array [
Object {
"actualDuration": 0,
"didRender": false,
"didRender": true,
"id": 5,
"label": "Memo(Child) key=\\"third\\"",
"label": "Memo(Child) key=\\"third\\" (<0.1ms of <0.1ms)",
"name": "Memo(Child)",
"offset": 15,
"selfDuration": 0,
@@ -318,6 +318,12 @@ Object {
"name": "Memo(Child)",
"value": 2,
},
Object {
"id": 5,
"label": "Memo(Child) key=\\"third\\" (<0.1ms)",
"name": "Memo(Child)",
"value": 0,
},
],
}
`;
+47 -17
View File
@@ -86,14 +86,21 @@ describe('profiling', () => {
it('should be collected for each commit', async done => {
const Parent = ({ count }) => {
Scheduler.advanceTime(10);
return new Array(count)
const children = new Array(count)
.fill(true)
.map((_, index) => <Child key={index} />);
.map((_, index) => <Child key={index} duration={index} />);
return (
<React.Fragment>
{children}
<MemoizedChild duration={1} />
</React.Fragment>
);
};
const Child = () => {
Scheduler.advanceTime(2);
const Child = ({ duration }) => {
Scheduler.advanceTime(duration);
return null;
};
const MemoizedChild = React.memo(Child);
const container = document.createElement('div');
@@ -158,14 +165,21 @@ describe('profiling', () => {
it('should be collected for each commit', async done => {
const Parent = ({ count }) => {
Scheduler.advanceTime(10);
return new Array(count)
const children = new Array(count)
.fill(true)
.map((_, index) => <Child key={index} />);
.map((_, index) => <Child key={index} duration={index} />);
return (
<React.Fragment>
{children}
<MemoizedChild duration={1} />
</React.Fragment>
);
};
const Child = () => {
Scheduler.advanceTime(2);
const Child = ({ duration }) => {
Scheduler.advanceTime(duration);
return null;
};
const MemoizedChild = React.memo(Child);
const container = document.createElement('div');
@@ -245,14 +259,21 @@ describe('profiling', () => {
it('should be collected for each rendered fiber', async done => {
const Parent = ({ count }) => {
Scheduler.advanceTime(10);
return new Array(count)
const children = new Array(count)
.fill(true)
.map((_, index) => <Child key={index} />);
.map((_, index) => <Child key={index} duration={index} />);
return (
<React.Fragment>
{children}
<MemoizedChild duration={1} />
</React.Fragment>
);
};
const Child = () => {
Scheduler.advanceTime(2);
const Child = ({ duration }) => {
Scheduler.advanceTime(duration);
return null;
};
const MemoizedChild = React.memo(Child);
const container = document.createElement('div');
@@ -339,14 +360,21 @@ describe('profiling', () => {
it('should be collected for every traced interaction', async done => {
const Parent = ({ count }) => {
Scheduler.advanceTime(10);
return new Array(count)
const children = new Array(count)
.fill(true)
.map((_, index) => <Child key={index} />);
.map((_, index) => <Child key={index} duration={index} />);
return (
<React.Fragment>
{children}
<MemoizedChild duration={1} />
</React.Fragment>
);
};
const Child = () => {
Scheduler.advanceTime(2);
const Child = ({ duration }) => {
Scheduler.advanceTime(duration);
return null;
};
const MemoizedChild = React.memo(Child);
const container = document.createElement('div');
@@ -419,7 +447,9 @@ describe('profiling', () => {
it('should remove profiling data when roots are unmounted', async () => {
const Parent = ({ count }) =>
new Array(count).fill(true).map((_, index) => <Child key={index} />);
new Array(count)
.fill(true)
.map((_, index) => <Child key={index} duration={index} />);
const Child = () => <div>Hi!</div>;
const containerA = document.createElement('div');
+7 -15
View File
@@ -645,18 +645,6 @@ export function attach(
}
}
function haveProfilerTimesChanged(
prevFiber: Fiber,
nextFiber: Fiber
): boolean {
return (
prevFiber.actualDuration !== undefined && // Short-circuit check for non-profiling builds
(prevFiber.actualDuration !== nextFiber.actualDuration ||
prevFiber.actualStartTime !== nextFiber.actualStartTime ||
prevFiber.treeBaseDuration !== nextFiber.treeBaseDuration)
);
}
let pendingOperations: Array<number> = [];
let pendingRealUnmountedIDs: Array<number> = [];
let pendingSimulatedUnmountedIDs: Array<number> = [];
@@ -843,8 +831,9 @@ export function attach(
pushOperation(treeBaseDuration);
const { actualDuration } = fiber;
if (actualDuration != null && actualDuration > 0) {
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(
@@ -1024,9 +1013,12 @@ export function attach(
pushOperation(treeBaseDuration);
}
if (alternate ? haveProfilerTimesChanged(alternate, fiber) : true) {
if (actualDuration != null && actualDuration > 0) {
if (alternate ? hasDataChanged(alternate, fiber) : true) {
if (actualDuration != null) {
// 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.maxActualDuration = Math.max(