From ee099124e241778d5d398b48c8eef99bc9c66361 Mon Sep 17 00:00:00 2001 From: Brian Vaughn Date: Wed, 8 May 2019 15:41:57 -0700 Subject: [PATCH] Fixed a Profiler memoization bug and improved test coverage --- .../__snapshots__/profiling-test.js.snap | 431 +++++++++++------- .../profilingCharts-test.js.snap | 10 +- src/__tests__/profiling-test.js | 64 ++- src/backend/renderer.js | 22 +- 4 files changed, 326 insertions(+), 201 deletions(-) diff --git a/src/__tests__/__snapshots__/profiling-test.js.snap b/src/__tests__/__snapshots__/profiling-test.js.snap index d508f633a5..fa3916d352 100644 --- a/src/__tests__/__snapshots__/profiling-test.js.snap +++ b/src/__tests__/__snapshots__/profiling-test.js.snap @@ -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, diff --git a/src/__tests__/__snapshots__/profilingCharts-test.js.snap b/src/__tests__/__snapshots__/profilingCharts-test.js.snap index 3cfc8bdfc9..feb708bac7 100644 --- a/src/__tests__/__snapshots__/profilingCharts-test.js.snap +++ b/src/__tests__/__snapshots__/profilingCharts-test.js.snap @@ -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, + }, ], } `; diff --git a/src/__tests__/profiling-test.js b/src/__tests__/profiling-test.js index 37b7d40ccc..8631c9c08a 100644 --- a/src/__tests__/profiling-test.js +++ b/src/__tests__/profiling-test.js @@ -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) => ); + .map((_, index) => ); + return ( + + {children} + + + ); }; - 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) => ); + .map((_, index) => ); + return ( + + {children} + + + ); }; - 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) => ); + .map((_, index) => ); + return ( + + {children} + + + ); }; - 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) => ); + .map((_, index) => ); + return ( + + {children} + + + ); }; - 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) => ); + new Array(count) + .fill(true) + .map((_, index) => ); const Child = () =>
Hi!
; const containerA = document.createElement('div'); diff --git a/src/backend/renderer.js b/src/backend/renderer.js index 23786c2bbd..c05c1dee05 100644 --- a/src/backend/renderer.js +++ b/src/backend/renderer.js @@ -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 = []; let pendingRealUnmountedIDs: Array = []; let pendingSimulatedUnmountedIDs: Array = []; @@ -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(