From 512b3a0e0c57f829f52f6f5c57c1601d96facd6b Mon Sep 17 00:00:00 2001 From: Luke Cotter <4013877+lukecotter@users.noreply.github.com> Date: Mon, 2 Dec 2024 16:37:21 +0000 Subject: [PATCH 1/3] refactor: add parent to Logline Object --- .../modules/__tests__/ApexLogParser.test.ts | 128 +++++++++++------- log-viewer/modules/parsers/ApexLogParser.ts | 4 + 2 files changed, 85 insertions(+), 47 deletions(-) diff --git a/log-viewer/modules/__tests__/ApexLogParser.test.ts b/log-viewer/modules/__tests__/ApexLogParser.test.ts index ddc1311d..c1cb2cca 100644 --- a/log-viewer/modules/__tests__/ApexLogParser.test.ts +++ b/log-viewer/modules/__tests__/ApexLogParser.test.ts @@ -88,6 +88,7 @@ describe('Pseudo EXIT events', () => { const processFound1 = log1.children[1] as Method; expect(processFound1).toMatchObject({ + parent: log1, type: 'WF_PROCESS_FOUND', timestamp: 2, duration: { self: 1, total: 1 }, @@ -95,6 +96,7 @@ describe('Pseudo EXIT events', () => { const approval2 = log1.children[2] as Method; expect(approval2).toMatchObject({ + parent: log1, type: 'WF_APPROVAL_SUBMIT', timestamp: 3, duration: { self: 1, total: 1 }, @@ -102,6 +104,7 @@ describe('Pseudo EXIT events', () => { const processFound2 = log1.children[3] as Method; expect(processFound2).toMatchObject({ + parent: log1, type: 'WF_PROCESS_FOUND', timestamp: 4, duration: { self: 0, total: 0 }, // no lines after the last WF_PROCESS_FOUND to use as an exit @@ -425,20 +428,24 @@ describe('parseLog tests', () => { expect(execEvent.children.length).toEqual(1); const soqlLine = execEvent.children[0] as SOQLExecuteBeginLine; - expect(soqlLine.type).toEqual('SOQL_EXECUTE_BEGIN'); - expect(soqlLine.aggregations).toEqual(2); - expect(soqlLine.rowCount.self).toEqual(50); - expect(soqlLine.rowCount.total).toEqual(50); + expect(soqlLine).toMatchObject({ + parent: execEvent, + type: 'SOQL_EXECUTE_BEGIN', + aggregations: 2, + rowCount: { self: 50, total: 50 }, + }); const soqlExplain = soqlLine.children[0] as SOQLExecuteExplainLine; - expect(soqlExplain.type).toEqual('SOQL_EXECUTE_EXPLAIN'); - expect(soqlExplain.type).toEqual('SOQL_EXECUTE_EXPLAIN'); - expect(soqlExplain.cardinality).toEqual(2); - expect(soqlExplain.fields).toEqual(['MyField__c', 'AnotherField__c']); - expect(soqlExplain.leadingOperationType).toEqual('TableScan'); - expect(soqlExplain.relativeCost).toEqual(1.3); - expect(soqlExplain.sObjectCardinality).toEqual(2); - expect(soqlExplain.sObjectType).toEqual('MySObject__c'); + expect(soqlExplain).toMatchObject({ + parent: soqlLine, + type: 'SOQL_EXECUTE_EXPLAIN', + cardinality: 2, + fields: ['MyField__c', 'AnotherField__c'], + leadingOperationType: 'TableScan', + relativeCost: 1.3, + sObjectCardinality: 2, + sObjectType: 'MySObject__c', + }); }); }); @@ -463,19 +470,28 @@ describe('getRootMethod tests', () => { expect(startLine?.children.length).toBe(1); const unitStart = startLine?.children[0] as CodeUnitStartedLine; - expect(unitStart.type).toBe('CODE_UNIT_STARTED'); - expect(unitStart.codeUnitType).toBe('Workflow'); + expect(unitStart).toMatchObject({ + parent: startLine, + type: 'CODE_UNIT_STARTED', + codeUnitType: 'Workflow', + }); expect(unitStart.children.length).toBe(1); const interViewsBegin = unitStart.children[0] as TimedNode; - expect(interViewsBegin.type).toBe('FLOW_START_INTERVIEWS_BEGIN'); - expect(interViewsBegin.text).toBe('FLOW_START_INTERVIEWS : Example Process Builder'); - expect(interViewsBegin.suffix).toBe(' (Process Builder)'); + expect(interViewsBegin).toMatchObject({ + parent: unitStart, + type: 'FLOW_START_INTERVIEWS_BEGIN', + text: 'FLOW_START_INTERVIEWS : Example Process Builder', + suffix: ' (Process Builder)', + }); expect(interViewsBegin.children.length).toBe(1); const interViewBegin = interViewsBegin.children[0]; - expect(interViewBegin?.type).toBe('FLOW_START_INTERVIEW_BEGIN'); - expect(interViewBegin?.duration).toEqual({ self: 6332706, total: 6332706 }); + expect(interViewBegin).toMatchObject({ + parent: interViewsBegin, + type: 'FLOW_START_INTERVIEW_BEGIN', + duration: { self: 6332706, total: 6332706 }, + }); }); it('FlowStartInterviewsBeginLine should be a flow ', async () => { @@ -627,35 +643,53 @@ describe('getRootMethod tests', () => { expect(apexLog.executionEndTime).toBe(1100); const rootChildren = apexLog.children as Method[]; - - const executionChildren = rootChildren[0]?.children as Method[]; + const executionStarted = rootChildren[0]; + const executionChildren = executionStarted?.children as Method[]; expect(executionChildren.length).toBe(5); - expect(executionChildren[0]?.type).toBe('METHOD_ENTRY'); - expect(executionChildren[0]?.timestamp).toBe(200); - expect(executionChildren[0]?.exitStamp).toBe(300); - expect(executionChildren[0]?.children.length).toBe(1); - expect(executionChildren[0]?.children[0]?.type).toBe('ENTERING_MANAGED_PKG'); - expect(executionChildren[0]?.children[0]?.namespace).toBe('ns'); - - expect(executionChildren[1]?.type).toBe('ENTERING_MANAGED_PKG'); - expect(executionChildren[1]?.namespace).toBe('ns'); - expect(executionChildren[1]?.timestamp).toBe(400); - expect(executionChildren[1]?.exitStamp).toBe(700); - - expect(executionChildren[2]?.type).toBe('ENTERING_MANAGED_PKG'); - expect(executionChildren[2]?.namespace).toBe('ns2'); - expect(executionChildren[2]?.timestamp).toBe(700); - expect(executionChildren[2]?.exitStamp).toBe(725); - - expect(executionChildren[3]?.type).toBe('DML_BEGIN'); - expect(executionChildren[3]?.timestamp).toBe(725); - expect(executionChildren[3]?.exitStamp).toBe(750); - - expect(executionChildren[4]?.type).toBe('ENTERING_MANAGED_PKG'); - expect(executionChildren[4]?.namespace).toBe('ns2'); - expect(executionChildren[4]?.timestamp).toBe(800); - expect(executionChildren[4]?.exitStamp).toBe(1100); - expect(executionChildren[4]?.children.length).toBe(0); + + expect(executionChildren[0]).toMatchObject({ + parent: executionStarted, + type: 'METHOD_ENTRY', + timestamp: 200, + exitStamp: 300, + children: [{ type: 'ENTERING_MANAGED_PKG', namespace: 'ns' }], + }); + + expect(executionChildren[1]).toMatchObject({ + parent: executionStarted, + type: 'ENTERING_MANAGED_PKG', + timestamp: 400, + exitStamp: 700, + children: [], + namespace: 'ns', + }); + + expect(executionChildren[2]).toMatchObject({ + parent: executionStarted, + type: 'ENTERING_MANAGED_PKG', + timestamp: 700, + exitStamp: 725, + children: [], + namespace: 'ns2', + }); + + expect(executionChildren[3]).toMatchObject({ + parent: executionStarted, + type: 'DML_BEGIN', + timestamp: 725, + exitStamp: 750, + children: [], + namespace: 'default', + }); + + expect(executionChildren[4]).toMatchObject({ + parent: executionStarted, + type: 'ENTERING_MANAGED_PKG', + timestamp: 800, + exitStamp: 1100, + children: [], + namespace: 'ns2', + }); }); }); diff --git a/log-viewer/modules/parsers/ApexLogParser.ts b/log-viewer/modules/parsers/ApexLogParser.ts index 9b6694ae..9af24b8c 100644 --- a/log-viewer/modules/parsers/ApexLogParser.ts +++ b/log-viewer/modules/parsers/ApexLogParser.ts @@ -164,6 +164,7 @@ export class ApexLogParser { if (line instanceof Method) { this.parseTree(line, lineIter, stack); } + line.parent = rootMethod; rootMethod.addChild(line); } rootMethod.setTimes(); @@ -225,6 +226,7 @@ export class ApexLogParser { this.parseTree(nextLine, lineIter, stack); } + nextLine.parent = currentLine; currentLine.children.push(nextLine); } @@ -487,6 +489,8 @@ export abstract class LogLine { // common metadata (available for all lines) + parent: LogLine | null = null; + /** * All child nodes of the current node */ From f979a81ff4fa500451fd2866d13204fb24a74953 Mon Sep 17 00:00:00 2001 From: Luke Cotter <4013877+lukecotter@users.noreply.github.com> Date: Mon, 2 Dec 2024 16:38:52 +0000 Subject: [PATCH 2/3] fix: analysis total time sum unique stacks Collect the stacks and only sum the unique entries e.g If we have an analysis like this methodA: 5s methodB: 3s methodC: 2s Sibling Methods The three methods are at the same level directly called from EXECUTION_STARTED. All 3 should be summed as they are in different stacks. Total: 10s Child Methods methodB is a child of methodA and methodC is a sibling of methodA. we first add methodA to the total but the total for methodB has already been accounted by including methodA so we skip it and any other children of methodA. methodC is in a unique stack and needs to be added to the total. Total: 7s --- log-viewer/modules/components/AnalysisView.ts | 8 +++- .../column-calcs/CallStackSum.ts | 46 +++++++++++++++++++ 2 files changed, 52 insertions(+), 2 deletions(-) create mode 100644 log-viewer/modules/components/analysis-view/column-calcs/CallStackSum.ts diff --git a/log-viewer/modules/components/AnalysisView.ts b/log-viewer/modules/components/AnalysisView.ts index d0b05814..0d824f55 100644 --- a/log-viewer/modules/components/AnalysisView.ts +++ b/log-viewer/modules/components/AnalysisView.ts @@ -21,6 +21,7 @@ import { vscodeMessenger } from '../services/VSCodeExtensionMessenger.js'; import { globalStyles } from '../styles/global.styles.js'; import './skeleton/GridSkeleton.js'; +import { callStackSum } from '../components/analysis-view/column-calcs/CallStackSum.js'; import { Find, formatter } from '../components/calltree-view/module/Find.js'; import { RowNavigation } from '../datagrid/module/RowNavigation.js'; @@ -191,7 +192,7 @@ export class AnalysisView extends LitElement { const methodMap: Map = new Map(); addNodeToMap(methodMap, rootMethod); - const metricList = [...methodMap.values()]; + const metricList = Array.from(methodMap.values()); const headerMenu = [ { @@ -328,7 +329,7 @@ export class AnalysisView extends LitElement { }, accessorDownload: NumberAccessor, bottomCalcFormatter: progressFormatter, - bottomCalc: 'max', + bottomCalc: callStackSum, bottomCalcFormatterParams: { precision: 3, totalValue: rootMethod.duration.total }, }, { @@ -377,11 +378,13 @@ export class Metric { totalTime = 0; selfTime = 0; namespace; + nodes: TimedNode[] = []; constructor(node: TimedNode) { this.name = node.text; this.type = node.type; this.namespace = node.namespace; + this.nodes.push(node); } } @@ -398,6 +401,7 @@ function addNodeToMap(map: Map, node: TimedNode, key?: string) { ++metric.count; metric.totalTime += node.duration.total; metric.selfTime += node.duration.self; + metric.nodes.push(node); } children.forEach(function (child) { diff --git a/log-viewer/modules/components/analysis-view/column-calcs/CallStackSum.ts b/log-viewer/modules/components/analysis-view/column-calcs/CallStackSum.ts new file mode 100644 index 00000000..b4373c6a --- /dev/null +++ b/log-viewer/modules/components/analysis-view/column-calcs/CallStackSum.ts @@ -0,0 +1,46 @@ +import type { LogLine, TimedNode } from '../../../parsers/ApexLogParser'; +import { type Metric } from '../../AnalysisView.js'; + +export function callStackSum(values: number[], data: Metric[], _calcParams: unknown) { + // All filtered debug logs nodes + const includedNodes = new Set(); + data.forEach((row) => { + row.nodes.forEach((node) => { + includedNodes.add(node); + }); + }); + + let total = 0; + data.forEach((row, i) => { + // All the parents (to root) of the log nodes for this row. + const parents = _getParentNodes(row.nodes); + // If any of these parent are else where in the (filtered) stacks do not include in the sum. + // This value will be included when the parent is summed e.g m1 -> m2 -> m3 (no need to include m2 + m3) + if (!_containsAny(parents, includedNodes)) { + total += values[i] ?? 0; + } + }); + + return total; +} + +const _getParentNodes = (nodes: TimedNode[]) => { + const parents = new Set(); + nodes.forEach((node) => { + let parent = node.parent; + while (parent && !parents.has(parent)) { + parents.add(parent); + parent = parent.parent; + } + }); + return parents; +}; + +const _containsAny = (target: Set, toCheck: Set) => { + for (const t of target) { + if (toCheck.has(t)) { + return true; + } + } + return false; +}; From 80dc522feb431b7d3bf75f04a3fe3e807ba7cbc5 Mon Sep 17 00:00:00 2001 From: Luke Cotter <4013877+lukecotter@users.noreply.github.com> Date: Mon, 2 Dec 2024 18:10:55 +0000 Subject: [PATCH 3/3] perf: improve performance summing total time on analysis --- log-viewer/modules/components/AnalysisView.ts | 36 +++++++------ .../column-calcs/CallStackSum.ts | 51 +++++++------------ 2 files changed, 39 insertions(+), 48 deletions(-) diff --git a/log-viewer/modules/components/AnalysisView.ts b/log-viewer/modules/components/AnalysisView.ts index 0d824f55..91fc5e4c 100644 --- a/log-viewer/modules/components/AnalysisView.ts +++ b/log-viewer/modules/components/AnalysisView.ts @@ -16,7 +16,7 @@ import NumberAccessor from '../datagrid/dataaccessor/Number.js'; import { progressFormatter } from '../datagrid/format/Progress.js'; import { RowKeyboardNavigation } from '../datagrid/module/RowKeyboardNavigation.js'; import dataGridStyles from '../datagrid/style/DataGrid.scss'; -import { ApexLog, TimedNode } from '../parsers/ApexLogParser.js'; +import { ApexLog, LogLine } from '../parsers/ApexLogParser.js'; import { vscodeMessenger } from '../services/VSCodeExtensionMessenger.js'; import { globalStyles } from '../styles/global.styles.js'; import './skeleton/GridSkeleton.js'; @@ -189,10 +189,7 @@ export class AnalysisView extends LitElement { if (!this.tableContainer) { return; } - const methodMap: Map = new Map(); - - addNodeToMap(methodMap, rootMethod); - const metricList = Array.from(methodMap.values()); + const metricList = groupMetrics(rootMethod); const headerMenu = [ { @@ -378,20 +375,29 @@ export class Metric { totalTime = 0; selfTime = 0; namespace; - nodes: TimedNode[] = []; + nodes: LogLine[] = []; - constructor(node: TimedNode) { + constructor(node: LogLine) { this.name = node.text; this.type = node.type; this.namespace = node.namespace; - this.nodes.push(node); } } -function addNodeToMap(map: Map, node: TimedNode, key?: string) { - const children = node.children; +function groupMetrics(root: LogLine) { + const methodMap: Map = new Map(); + + for (const child of root.children) { + if (child.duration.total) { + addNodeToMap(methodMap, child); + } + } + return Array.from(methodMap.values()); +} - if (key) { +function addNodeToMap(map: Map, node: LogLine) { + if (node.duration.total) { + const key = node.namespace + node.text; let metric = map.get(key); if (!metric) { metric = new Metric(node); @@ -404,11 +410,11 @@ function addNodeToMap(map: Map, node: TimedNode, key?: string) { metric.nodes.push(node); } - children.forEach(function (child) { - if (child instanceof TimedNode) { - addNodeToMap(map, child, child.namespace + child.text); + for (const child of node.children) { + if (child.duration.total) { + addNodeToMap(map, child); } - }); + } } type VSCodeSaveFile = { diff --git a/log-viewer/modules/components/analysis-view/column-calcs/CallStackSum.ts b/log-viewer/modules/components/analysis-view/column-calcs/CallStackSum.ts index b4373c6a..a3540509 100644 --- a/log-viewer/modules/components/analysis-view/column-calcs/CallStackSum.ts +++ b/log-viewer/modules/components/analysis-view/column-calcs/CallStackSum.ts @@ -1,46 +1,31 @@ -import type { LogLine, TimedNode } from '../../../parsers/ApexLogParser'; +import type { LogLine } from '../../../parsers/ApexLogParser'; import { type Metric } from '../../AnalysisView.js'; -export function callStackSum(values: number[], data: Metric[], _calcParams: unknown) { - // All filtered debug logs nodes - const includedNodes = new Set(); - data.forEach((row) => { - row.nodes.forEach((node) => { - includedNodes.add(node); - }); - }); +export function callStackSum(_values: number[], data: Metric[], _calcParams: unknown) { + const nodes: LogLine[] = []; + for (const row of data) { + Array.prototype.push.apply(nodes, row.nodes); + } + const allNodes = new Set(nodes); let total = 0; - data.forEach((row, i) => { - // All the parents (to root) of the log nodes for this row. - const parents = _getParentNodes(row.nodes); - // If any of these parent are else where in the (filtered) stacks do not include in the sum. - // This value will be included when the parent is summed e.g m1 -> m2 -> m3 (no need to include m2 + m3) - if (!_containsAny(parents, includedNodes)) { - total += values[i] ?? 0; + for (const node of nodes) { + if (!_isChildOfOther(node, allNodes)) { + total += node.duration.total; } - }); + } return total; } -const _getParentNodes = (nodes: TimedNode[]) => { - const parents = new Set(); - nodes.forEach((node) => { - let parent = node.parent; - while (parent && !parents.has(parent)) { - parents.add(parent); - parent = parent.parent; - } - }); - return parents; -}; - -const _containsAny = (target: Set, toCheck: Set) => { - for (const t of target) { - if (toCheck.has(t)) { +function _isChildOfOther(node: LogLine, filteredNodes: Set) { + let parent = node.parent; + while (parent) { + if (filteredNodes.has(parent)) { return true; } + parent = parent.parent; } + return false; -}; +}