From 9507c73a152da6a8ce437deff38abc12210a6680 Mon Sep 17 00:00:00 2001 From: Luke Cotter <4013877+lukecotter@users.noreply.github.com> Date: Mon, 15 Jan 2024 17:42:32 +0000 Subject: [PATCH 1/9] perf: switched to a generator function for pasing to log lines In testing parsing of a large 70mb log went from ~2s to 1.3s, roughly 35% (~1.3 times) faster. - Improved performance by reducing down to 1 loop when creating and parsing log lines (generator function). - Instead of placing all the line strings in memory upfront (giant array), we do it as each line needs them. - The line iterator now only has one line in memory. - Avoid high GC cost by manually splitting strings on new line character instead of using string split. --- log-viewer/modules/__tests__/Database.test.ts | 6 +- log-viewer/modules/parsers/ApexLogParser.ts | 107 +++++++++--------- 2 files changed, 57 insertions(+), 56 deletions(-) diff --git a/log-viewer/modules/__tests__/Database.test.ts b/log-viewer/modules/__tests__/Database.test.ts index b2e7e8eb..8d8e1ff3 100644 --- a/log-viewer/modules/__tests__/Database.test.ts +++ b/log-viewer/modules/__tests__/Database.test.ts @@ -2,7 +2,7 @@ * Copyright (c) 2020 Certinia Inc. All rights reserved. */ import { DatabaseAccess } from '../Database.js'; -import logParser from '../parsers/ApexLogParser.js'; +import { parse } from '../parsers/ApexLogParser.js'; describe('Analyse database tests', () => { it('Only DML and SOQL are collected', async () => { @@ -16,10 +16,10 @@ describe('Analyse database tests', () => { '09:19:13.82 (51592737891)|CODE_UNIT_FINISHED|pse.VFRemote: pse.SenchaTCController invoke(saveTimecard)\n' + '09:19:13.82 (51595120059)|EXECUTION_FINISHED\n'; - const apexLog = new logParser().parse(log); + const apexLog = parse(log); const result = await DatabaseAccess.create(apexLog); const firstSOQL = result.getSOQLLines()[0]; - + console.debug('a', apexLog, result); expect(firstSOQL?.text).toEqual('SELECT Id FROM Account'); const firstDML = result.getDMLLines()[0]; diff --git a/log-viewer/modules/parsers/ApexLogParser.ts b/log-viewer/modules/parsers/ApexLogParser.ts index d344681a..e909b066 100644 --- a/log-viewer/modules/parsers/ApexLogParser.ts +++ b/log-viewer/modules/parsers/ApexLogParser.ts @@ -37,7 +37,7 @@ export function parse(logData: string): ApexLog { * const apexLog = new ApexLogParser().parse(logText); * const apexLog = parse(logText); */ -export default class ApexLogParser { +class ApexLogParser { logIssues: LogIssue[] = []; parsingErrors: string[] = []; maxSizeTimestamp: number | null = null; @@ -53,9 +53,8 @@ export default class ApexLogParser { * @returns {ApexLog} */ parse(debugLog: string): ApexLog { - const logLines = this.parseLog(debugLog); - - const apexLog = this.toLogTree(logLines); + const lineGenerator = this.generateLogLines(debugLog); + const apexLog = this.toLogTree(lineGenerator); apexLog.size = debugLog.length; apexLog.debugLevels = this.getDebugLevels(debugLog); apexLog.logIssues = this.logIssues; @@ -110,65 +109,67 @@ export default class ApexLogParser { return null; } - private parseLog(log: string): LogLine[] { + private *generateLogLines(log: string): Generator { const start = log.match(/^.*EXECUTION_STARTED.*$/m)?.index || 0; - const rawLines = this.splitByNextLine(log.slice(start)); - - // reset global variables to be captured during parsing - this.logIssues = []; - this.reasons = new Set(); - this.cpuUsed = 0; - this.discontinuity = false; + if (start > 0) { + log = log.slice(start); + } - const logLines = []; + const hascrlf = log.indexOf('\r\n') > -1; let lastEntry = null; - const len = rawLines.length; - for (let i = 0; i < len; i++) { - const line = rawLines[i]; + let eolIndex = log.indexOf('\n'); + let startIndex = 0; + let crlfIndex = -1; + + while (eolIndex !== -1) { + if (hascrlf && eolIndex > crlfIndex) { + crlfIndex = log.indexOf('\r', startIndex); + } + const line = log.slice(startIndex, crlfIndex + 1 === eolIndex ? crlfIndex : eolIndex); if (line) { // ignore blank lines const entry = this.parseLine(line, lastEntry); if (entry) { - logLines.push(entry); lastEntry = entry; + yield entry; } } + startIndex = eolIndex + 1; + eolIndex = log.indexOf('\n', startIndex); } - lastEntry?.onAfter?.(this); - - return logLines; - } - // Matches CRLF (\r\n) + LF (\n) - // the ? matches the previous token 0 or 1 times. - private splitByNextLine(text: string) { - const hascrlfEOL = text.indexOf('\r\n') > -1; - let regex; - if (!hascrlfEOL) { - regex = /\n/; - } else { - regex = /\r?\n/; + // Parse the last line + const line = log.slice(startIndex, log.length); + if (line) { + // ignore blank lines + const entry = this.parseLine(line, lastEntry); + if (entry) { + entry?.onAfter?.(this); + yield entry; + } } - return text.split(regex); } - private toLogTree(logLines: LogLine[]) { - const lineIter = new LineIterator(logLines), - rootMethod = new ApexLog(), + private toLogTree(lineGenerator: Generator) { + const rootMethod = new ApexLog(), stack: Method[] = []; let line: LogLine | null; - this.lastTimestamp = 0; - while ((line = lineIter.fetch())) { - if (line instanceof Method) { - this.parseTree(line, lineIter, stack); + + if (currentParser) { + const lineIter = new LineIterator(lineGenerator); + + while ((line = lineIter.fetch())) { + if (line instanceof Method) { + this.parseTree(line, lineIter, stack); + } + rootMethod.addChild(line); } - rootMethod.addChild(line); - } - rootMethod.setTimes(); + rootMethod.setTimes(); - this.insertPackageWrappers(rootMethod); - this.aggregateTotals(rootMethod.children); + this.insertPackageWrappers(rootMethod); + this.aggregateTotals([rootMethod]); + } return rootMethod; } @@ -456,22 +457,22 @@ export class DebugLevel { } export class LineIterator { - lines: LogLine[]; - index: number; - length: number; + next: LogLine | null = null; + lineGenerator: Generator; - constructor(lines: LogLine[]) { - this.lines = lines; - this.index = 0; - this.length = lines.length; + constructor(lineGenerator: Generator) { + this.lineGenerator = lineGenerator; + this.next = this.lineGenerator.next().value; } peek(): LogLine | null { - return this.index < this.length ? this.lines[this.index] || null : null; + return this.next; } fetch(): LogLine | null { - return this.index < this.length ? this.lines[this.index++] || null : null; + const result = this.next; + this.next = this.lineGenerator.next().value; + return result; } } @@ -797,7 +798,7 @@ export class ApexLog extends Method { endTime ??= child?.timestamp; } this.exitStamp = endTime || 0; - this.duration.total = this.exitStamp - this.timestamp; + this.recalculateDurations(); } } From 5c95705f3b165e6d9538d4dcb8b05dfa9d994c49 Mon Sep 17 00:00:00 2001 From: Luke Cotter <4013877+lukecotter@users.noreply.github.com> Date: Mon, 22 Jan 2024 15:13:13 +0000 Subject: [PATCH 2/9] style: remove debug --- log-viewer/modules/__tests__/Database.test.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/log-viewer/modules/__tests__/Database.test.ts b/log-viewer/modules/__tests__/Database.test.ts index 8d8e1ff3..e2f605be 100644 --- a/log-viewer/modules/__tests__/Database.test.ts +++ b/log-viewer/modules/__tests__/Database.test.ts @@ -18,8 +18,8 @@ describe('Analyse database tests', () => { const apexLog = parse(log); const result = await DatabaseAccess.create(apexLog); + const firstSOQL = result.getSOQLLines()[0]; - console.debug('a', apexLog, result); expect(firstSOQL?.text).toEqual('SELECT Id FROM Account'); const firstDML = result.getDMLLines()[0]; From 98ef1ee363b812234350ee05afbba0d4985de84b Mon Sep 17 00:00:00 2001 From: Luke Cotter <4013877+lukecotter@users.noreply.github.com> Date: Mon, 22 Jan 2024 16:50:37 +0000 Subject: [PATCH 3/9] perf: avoid duplicate namespace parsing work Return namespace from a cache and avoid allocating extra strings to do the same namespace parsing work repeatedly. --- log-viewer/modules/parsers/ApexLogParser.ts | 71 ++++++++++++++++----- 1 file changed, 56 insertions(+), 15 deletions(-) diff --git a/log-viewer/modules/parsers/ApexLogParser.ts b/log-viewer/modules/parsers/ApexLogParser.ts index 7a7521d5..becaff01 100644 --- a/log-viewer/modules/parsers/ApexLogParser.ts +++ b/log-viewer/modules/parsers/ApexLogParser.ts @@ -45,7 +45,7 @@ class ApexLogParser { cpuUsed = 0; lastTimestamp = 0; discontinuity = false; - namespaces = new Set(); + namespaces: string[] = []; /** * Takes string input of a log and returns the ApexLog class, which represents a log tree @@ -74,7 +74,9 @@ class ApexLogParser { const entry = new metaCtor(parts); entry.logLine = line; lastEntry?.onAfter?.(this, entry); - entry.namespace && this.namespaces.add(entry.namespace); + entry.namespace && + !this.namespaces.includes(entry.namespace) && + this.namespaces.push(entry.namespace); return entry; } @@ -124,7 +126,7 @@ class ApexLogParser { while (eolIndex !== -1) { if (hascrlf && eolIndex > crlfIndex) { - crlfIndex = log.indexOf('\r', startIndex); + crlfIndex = log.indexOf('\r', eolIndex - 1); } const line = log.slice(startIndex, crlfIndex + 1 === eolIndex ? crlfIndex : eolIndex); if (line) { @@ -836,6 +838,52 @@ export function parseVfNamespace(text: string): string { return text.substring(secondSlash + 1, sep); } +export function parseMethodNamespace(methodName: string): string { + const methodBracketIndex = methodName.indexOf('('); + if (methodBracketIndex === -1) { + return ''; + } + + let possibleNs = methodName.slice(0, methodName.indexOf('.')); + possibleNs = + currentParser?.namespaces.find((ns) => { + return ns === possibleNs; + }) || ''; + + if (possibleNs) { + return possibleNs; + } + + const methodNameParts = methodName ? methodName.slice(0, methodBracketIndex)?.split('.') : ''; + if (methodNameParts.length === 4) { + return methodNameParts[0] ?? ''; + } else if (methodNameParts.length === 2) { + return 'default'; + } + + return ''; +} + +export function parseConstructorNamespace(className: string): string { + let possibleNs = className.slice(0, className.indexOf('.')); + possibleNs = + currentParser?.namespaces.find((ns) => { + return ns === possibleNs; + }) || ''; + + if (possibleNs) { + return possibleNs; + } + const constructorParts = (className ?? '').split('.'); + possibleNs = constructorParts[0] || ''; + // inmner class with a namespace + if (constructorParts.length === 3) { + return possibleNs; + } + + return ''; +} + export function parseRows(text: string | null | undefined): number { if (!text) { return 0; @@ -903,11 +951,9 @@ class ConstructorEntryLine extends Method { const [, , , , args, className] = parts; this.text = className + (args ? args.substring(args.lastIndexOf('(')) : ''); - const constructorParts = (className ?? '').split('.'); - const possibleNs = constructorParts[0] || ''; - // inmner class with a namespace - if (constructorParts.length === 3 || currentParser?.namespaces.has(possibleNs)) { - this.namespace = possibleNs ?? this.namespace; + const possibleNS = parseConstructorNamespace(className || ''); + if (possibleNS) { + this.namespace = possibleNS; } } } @@ -929,7 +975,6 @@ class EmailQueueLine extends LogLine { } } -// todo: avoid some of ns parsing work if we have done it before. export class MethodEntryLine extends Method { hasValidSymbols = true; @@ -941,12 +986,8 @@ export class MethodEntryLine extends Method { // assume we are not charged for class loading (or at least not lengthy remote-loading / compiling) this.cpuType = 'loading'; } else { - const methodName = parts[4] || ''; - const methodNameParts = methodName - ? methodName.slice(0, methodName.indexOf('('))?.split('.') - : ''; - const possibleNs = methodNameParts[0] ?? ''; - if (methodNameParts.length === 4 || currentParser?.namespaces.has(possibleNs)) { + const possibleNs = parseMethodNamespace(parts[4] || ''); + if (possibleNs) { this.namespace = possibleNs; } } From 71b658ee5e0845c8c4c5cff125693d2fdf40af55 Mon Sep 17 00:00:00 2001 From: Luke Cotter <4013877+lukecotter@users.noreply.github.com> Date: Mon, 22 Jan 2024 17:23:40 +0000 Subject: [PATCH 4/9] perf: replace substring with slice --- log-viewer/modules/parsers/ApexLogParser.ts | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/log-viewer/modules/parsers/ApexLogParser.ts b/log-viewer/modules/parsers/ApexLogParser.ts index becaff01..b9762a60 100644 --- a/log-viewer/modules/parsers/ApexLogParser.ts +++ b/log-viewer/modules/parsers/ApexLogParser.ts @@ -816,10 +816,10 @@ export function parseObjectNamespace(text: string | null | undefined): string { } const sep = text.indexOf('__'); - if (sep < 0) { + if (sep === -1) { return 'default'; } - return text.substring(0, sep); + return text.slice(0, sep); } export function parseVfNamespace(text: string): string { From 151df7c5049dda3df94a7bfc31505e6f592f231d Mon Sep 17 00:00:00 2001 From: Luke Cotter <4013877+lukecotter@users.noreply.github.com> Date: Mon, 22 Jan 2024 17:25:19 +0000 Subject: [PATCH 5/9] perf: reorder matchingend conditions so most likely is earlier This wil reduce the num of condition check needed --- log-viewer/modules/parsers/ApexLogParser.ts | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/log-viewer/modules/parsers/ApexLogParser.ts b/log-viewer/modules/parsers/ApexLogParser.ts index b9762a60..baa40f88 100644 --- a/log-viewer/modules/parsers/ApexLogParser.ts +++ b/log-viewer/modules/parsers/ApexLogParser.ts @@ -269,9 +269,9 @@ class ApexLogParser { return ( endLine.type && startMethod.exitTypes.includes(endLine.type) && - (!endLine.lineNumber || - !startMethod.lineNumber || - endLine.lineNumber === startMethod.lineNumber) + (endLine.lineNumber === startMethod.lineNumber || + !endLine.lineNumber || + !startMethod.lineNumber) ); } From 2a8535be553359f2d2588a8d3213ba190149bed9 Mon Sep 17 00:00:00 2001 From: Luke Cotter <4013877+lukecotter@users.noreply.github.com> Date: Mon, 22 Jan 2024 17:26:39 +0000 Subject: [PATCH 6/9] perf: use or assignment operator This reduce number of right hands boolean condtion checks when left hand side is already true. --- log-viewer/modules/parsers/ApexLogParser.ts | 5 +---- 1 file changed, 1 insertion(+), 4 deletions(-) diff --git a/log-viewer/modules/parsers/ApexLogParser.ts b/log-viewer/modules/parsers/ApexLogParser.ts index baa40f88..796da28c 100644 --- a/log-viewer/modules/parsers/ApexLogParser.ts +++ b/log-viewer/modules/parsers/ApexLogParser.ts @@ -187,10 +187,7 @@ class ApexLogParser { stack.push(currentLine); while ((nextLine = lineIter.peek())) { - if (nextLine.discontinuity) { - // discontinuities are stack unwinding (caused by Exceptions) - this.discontinuity = true; // start unwinding stack - } + this.discontinuity ||= nextLine.discontinuity; // start unwinding stack if ( exitOnNextLine && From a48e1f1ff665b065c6c76c408b02c28867b4ba0d Mon Sep 17 00:00:00 2001 From: Luke Cotter <4013877+lukecotter@users.noreply.github.com> Date: Mon, 22 Jan 2024 17:27:01 +0000 Subject: [PATCH 7/9] perf: change lastTimeStamp to be local var --- log-viewer/modules/parsers/ApexLogParser.ts | 25 ++++++++++----------- 1 file changed, 12 insertions(+), 13 deletions(-) diff --git a/log-viewer/modules/parsers/ApexLogParser.ts b/log-viewer/modules/parsers/ApexLogParser.ts index 796da28c..58a6ed2b 100644 --- a/log-viewer/modules/parsers/ApexLogParser.ts +++ b/log-viewer/modules/parsers/ApexLogParser.ts @@ -43,7 +43,6 @@ class ApexLogParser { maxSizeTimestamp: number | null = null; reasons: Set = new Set(); cpuUsed = 0; - lastTimestamp = 0; discontinuity = false; namespaces: string[] = []; @@ -157,7 +156,6 @@ class ApexLogParser { const rootMethod = new ApexLog(), stack: Method[] = []; let line: LogLine | null; - this.lastTimestamp = 0; if (currentParser) { const lineIter = new LineIterator(lineGenerator); @@ -177,7 +175,7 @@ class ApexLogParser { } private parseTree(currentLine: Method, lineIter: LineIterator, stack: Method[]) { - this.lastTimestamp = currentLine.timestamp; + let lastTimestamp = currentLine.timestamp; currentLine.namespace ||= 'default'; const isEntry = currentLine.exitTypes.length > 0; @@ -186,7 +184,10 @@ class ApexLogParser { let nextLine; stack.push(currentLine); + while ((nextLine = lineIter.peek())) { + lastTimestamp = nextLine.timestamp; + // discontinuities are stack unwinding (caused by Exceptions) this.discontinuity ||= nextLine.discontinuity; // start unwinding stack if ( @@ -204,10 +205,8 @@ class ApexLogParser { nextLine.isExit && this.endMethod(currentLine, nextLine, lineIter, stack) ) { - if (currentLine.onEnd) { - // the method wants to see the exit line - currentLine.onEnd(nextLine, stack); - } + // the method wants to see the exit line + currentLine.onEnd?.(nextLine, stack); break; } @@ -223,23 +222,23 @@ class ApexLogParser { nextLine.namespace ||= currentLine.namespace || 'default'; lineIter.fetch(); // it's a child - consume the line - this.lastTimestamp = nextLine.timestamp; + if (nextLine instanceof Method) { this.parseTree(nextLine, lineIter, stack); } - currentLine.addChild(nextLine); + currentLine.children.push(nextLine); } // End of line error handling. We have finished processing this log line and either got to the end // of the log without finding an exit line or the current line was truncated) if (!nextLine || currentLine.isTruncated) { // truncated method - terminate at the end of the log - currentLine.exitStamp = this.lastTimestamp; + currentLine.exitStamp = lastTimestamp; // we found an entry event on its own e.g a `METHOD_ENTRY` without a `METHOD_EXIT` and got to the end of the log this.addLogIssue( - this.lastTimestamp, + lastTimestamp, 'Unexpected-End', 'An entry event was found without a corresponding exit event e.g a `METHOD_ENTRY` event without a `METHOD_EXIT`', 'unexpected', @@ -247,12 +246,12 @@ class ApexLogParser { if (currentLine.isTruncated) { this.updateLogIssue( - this.lastTimestamp, + lastTimestamp, 'Max-Size-reached', 'The maximum log size has been reached. Part of the log has been truncated.', 'skip', ); - this.maxSizeTimestamp = this.lastTimestamp; + this.maxSizeTimestamp = lastTimestamp; } currentLine.isTruncated = true; } From 442ef7939488fd626cf4a2c7a801fe54e9905eb1 Mon Sep 17 00:00:00 2001 From: Luke Cotter <4013877+lukecotter@users.noreply.github.com> Date: Mon, 22 Jan 2024 17:43:27 +0000 Subject: [PATCH 8/9] refactor: no need to convert to array It already is an array --- log-viewer/modules/parsers/ApexLogParser.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/log-viewer/modules/parsers/ApexLogParser.ts b/log-viewer/modules/parsers/ApexLogParser.ts index 58a6ed2b..80bf82c6 100644 --- a/log-viewer/modules/parsers/ApexLogParser.ts +++ b/log-viewer/modules/parsers/ApexLogParser.ts @@ -59,7 +59,7 @@ class ApexLogParser { apexLog.logIssues = this.logIssues; apexLog.parsingErrors = this.parsingErrors; apexLog.cpuTime = this.cpuUsed; - apexLog.namespaces = [...this.namespaces]; + apexLog.namespaces = this.namespaces; return apexLog; } From 14674915dc70aae39139f11a391e93fe64d4bc7f Mon Sep 17 00:00:00 2001 From: Luke Cotter <4013877+lukecotter@users.noreply.github.com> Date: Wed, 24 Jan 2024 21:56:00 +0000 Subject: [PATCH 9/9] docs: update changelog --- CHANGELOG.md | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 0f71773e..df93b8ee 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -15,7 +15,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Changed -- Go to File multiple workspace handling to be simpified ([#202][#202]) +- Apex Log Parser Speed improveed to between 2 and 3 faster ([#475][#475]) +- Go to file multiple workspace handling simplified ([#202][#202]) - Go to file from Call Tree will only ask you to select a workspace if more than one matching file is found in multiple workspaces, instead of everytime. ## [1.12.1] - 2023-12-11 @@ -327,6 +328,7 @@ Skipped due to adopting odd numbering for pre releases and even number for relea +[#475]: https://github.com/certinia/debug-log-analyzer/issues/475 [#299]: https://github.com/certinia/debug-log-analyzer/issues/299 [#202]: https://github.com/certinia/debug-log-analyzer/issues/202