From cf99c3ee6c63749c0f2453ec325622c03558a2f0 Mon Sep 17 00:00:00 2001 From: Brian Vaughn Date: Mon, 13 May 2019 10:13:29 -0700 Subject: [PATCH] Moved calculation of self duration to the backend/renderer This enables self duration to be computed accurately despite component filters --- .../__snapshots__/profiling-test.js.snap | 179 +++++++++++++++--- src/__tests__/profiling-test.js | 135 +++++++++++++ src/backend/renderer.js | 74 ++++---- src/backend/types.js | 3 +- src/devtools/ProfilingCache.js | 19 +- .../views/Profiler/FlamegraphChartBuilder.js | 6 +- .../views/Profiler/RankedChartBuilder.js | 6 +- src/devtools/views/Profiler/types.js | 1 + src/devtools/views/Profiler/utils.js | 34 +--- 9 files changed, 342 insertions(+), 115 deletions(-) diff --git a/src/__tests__/__snapshots__/profiling-test.js.snap b/src/__tests__/__snapshots__/profiling-test.js.snap index fa3916d352..fce6058d97 100644 --- a/src/__tests__/__snapshots__/profiling-test.js.snap +++ b/src/__tests__/__snapshots__/profiling-test.js.snap @@ -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, }, diff --git a/src/__tests__/profiling-test.js b/src/__tests__/profiling-test.js index 26d2e2e678..dd085a5fa4 100644 --- a/src/__tests__/profiling-test.js +++ b/src/__tests__/profiling-test.js @@ -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 ( + + + + + ); + }; + const Parent = () => { + Scheduler.advanceTime(2); + return ; + }; + const Child = () => { + Scheduler.advanceTime(1); + return null; + }; + + utils.act(() => store.startProfiling()); + utils.act(() => + ReactDOM.render(, 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( + + + + ); + }); + + 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 ( + }> + + + ); + }; + 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(, 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( + + + + ); + }); + } + + expect(allCommitDetails).toHaveLength(2); + + done(); + }); }); describe('FiberCommits', () => { diff --git a/src/backend/renderer.js b/src/backend/renderer.js index b76ce8a7d6..fdbdd694c2 100644 --- a/src/backend/renderer.js +++ b/src/backend/renderer.js @@ -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, commitTime: number, + durations: Array, interactions: Array, 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; } } diff --git a/src/backend/types.js b/src/backend/types.js index a9680cd78a..9ec9ec70a1 100644 --- a/src/backend/types.js +++ b/src/backend/types.js @@ -122,8 +122,9 @@ export type InteractionBackend = {| |}; export type CommitDetailsBackend = {| - actualDurations: Array, commitIndex: number, + // Tuple of id, actual duration, and (computed) self duration + durations: Array, interactions: Array, rootID: number, |}; diff --git a/src/devtools/ProfilingCache.js b/src/devtools/ProfilingCache.js index 9ef88565c8..ac679f570f 100644 --- a/src/devtools/ProfilingCache.js +++ b/src/devtools/ProfilingCache.js @@ -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, }); } diff --git a/src/devtools/views/Profiler/FlamegraphChartBuilder.js b/src/devtools/views/Profiler/FlamegraphChartBuilder.js index 8f314ba754..7d5b552506 100644 --- a/src/devtools/views/Profiler/FlamegraphChartBuilder.js +++ b/src/devtools/views/Profiler/FlamegraphChartBuilder.js @@ -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'; diff --git a/src/devtools/views/Profiler/RankedChartBuilder.js b/src/devtools/views/Profiler/RankedChartBuilder.js index f11c97200f..51f0919a22 100644 --- a/src/devtools/views/Profiler/RankedChartBuilder.js +++ b/src/devtools/views/Profiler/RankedChartBuilder.js @@ -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'; diff --git a/src/devtools/views/Profiler/types.js b/src/devtools/views/Profiler/types.js index 0da7a99225..38b4742ac6 100644 --- a/src/devtools/views/Profiler/types.js +++ b/src/devtools/views/Profiler/types.js @@ -31,6 +31,7 @@ export type CommitDetailsFrontend = {| rootID: number, commitIndex: number, actualDurations: Map, + selfDurations: Map, interactions: Array, |}; diff --git a/src/devtools/views/Profiler/utils.js b/src/devtools/views/Profiler/utils.js index 93443d9714..b1c6a27a30 100644 --- a/src/devtools/views/Profiler/utils.js +++ b/src/devtools/views/Profiler/utils.js @@ -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>, profilingSnapshots: Map>,