From 53c3e104821df7b45223b9a1d1ee48deeca827cc Mon Sep 17 00:00:00 2001 From: Camillo Bruni Date: Thu, 4 Aug 2022 12:33:53 +0200 Subject: [PATCH] [tools] Fix parse-processor - Update parse processor to use new async log-reader functions - Fix some typos - Add more desciptions to the output - Update bytes and time formatting to use common helper.mjs functions Bug: v8:13146 Change-Id: Idf58a394aa493b7f50ad5282533c1b6d326117be Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/3810233 Reviewed-by: Victor Gomes Commit-Queue: Camillo Bruni Cr-Commit-Position: refs/heads/main@{#82206} --- tools/js/helper.mjs | 17 ++++++---- tools/parse-processor.html | 4 +-- tools/parse-processor.mjs | 69 ++++++++++++++++++++------------------ 3 files changed, 50 insertions(+), 40 deletions(-) diff --git a/tools/js/helper.mjs b/tools/js/helper.mjs index 25333b407c..0701507cf4 100644 --- a/tools/js/helper.mjs +++ b/tools/js/helper.mjs @@ -23,16 +23,21 @@ export function formatMicroSeconds(micro) { return (micro * kMicro2Milli).toFixed(1) + 'ms'; } -export function formatDurationMicros(micros, secondsDigits = 3) { - return formatDurationMillis(micros * kMicro2Milli, secondsDigits); +export function formatDurationMicros(micros, digits = 3) { + return formatDurationMillis(micros * kMicro2Milli, digits); } -export function formatDurationMillis(millis, secondsDigits = 3) { +export function formatMillis(millis, digits = 3) { + return formatDurationMillis(millis, digits); +} + +export function formatDurationMillis(millis, digits = 3) { if (millis < 1000) { if (millis < 1) { - return (millis / kMicro2Milli).toFixed(1) + 'ns'; + if (millis == 0) return (0).toFixed(digits) + 's'; + return (millis / kMicro2Milli).toFixed(digits) + 'ns'; } - return millis.toFixed(2) + 'ms'; + return millis.toFixed(digits) + 'ms'; } let seconds = millis / 1000; const hours = Math.floor(seconds / 3600); @@ -41,7 +46,7 @@ export function formatDurationMillis(millis, secondsDigits = 3) { let buffer = ''; if (hours > 0) buffer += hours + 'h '; if (hours > 0 || minutes > 0) buffer += minutes + 'm '; - buffer += seconds.toFixed(secondsDigits) + 's'; + buffer += seconds.toFixed(digits) + 's'; return buffer; } diff --git a/tools/parse-processor.html b/tools/parse-processor.html index fa7033f43c..495a21d655 100644 --- a/tools/parse-processor.html +++ b/tools/parse-processor.html @@ -130,11 +130,11 @@ document.loadFile = function() { let file = files[0]; let reader = new FileReader(); - reader.onload = function(evt) { + reader.onload = async function(evt) { const kTimerName = 'parse log file'; console.time(kTimerName); let parseProcessor = new ParseProcessor(); - parseProcessor.processString(this.result); + await parseProcessor.processString(this.result); console.timeEnd(kTimerName); renderParseResults(parseProcessor); document.parseProcessor = parseProcessor; diff --git a/tools/parse-processor.mjs b/tools/parse-processor.mjs index fc5868b008..00b5919f43 100644 --- a/tools/parse-processor.mjs +++ b/tools/parse-processor.mjs @@ -3,6 +3,7 @@ // found in the LICENSE file. import { LogReader, parseString } from "./logreader.mjs"; import { BaseArgumentsProcessor } from "./arguments.mjs"; +import { formatBytes, formatMillis} from "./js/helper.mjs"; // =========================================================================== @@ -20,20 +21,17 @@ function formatNumber(value) { } export function BYTES(bytes, total) { - let units = ['B ', 'kB', 'mB', 'gB']; - let unitIndex = 0; - let value = bytes; - while (value > 1000 && unitIndex < units.length) { - value /= 1000; - unitIndex++; - } - let result = formatNumber(value).padStart(10) + ' ' + units[unitIndex]; + let result = formatBytes(bytes) if (total !== undefined && total != 0) { result += PERCENT(bytes, total).padStart(5); } return result; } +export function TIME(millis) { + return formatMillis(millis, 1); +} + export function PERCENT(value, total) { return Math.round(value / total * 100) + "%"; } @@ -264,7 +262,7 @@ class Script extends CompilationUnit { this.maxNestingLevel = maxNesting; // Initialize sizes. - if (!this.ownBytes === -1) throw 'Invalid state'; + if (this.ownBytes === -1) console.error('Invalid ownBytes'); if (this.funktions.length == 0) { this.bytesTotal = this.ownBytes = 0; return; @@ -340,9 +338,9 @@ class Script extends CompilationUnit { let info = (name, funktions) => { let ownBytes = ownBytesSum(funktions); let nofPercent = Math.round(funktions.length / nofFunktions * 100); - let value = (funktions.length + "").padStart(6) + + let value = (funktions.length + "#").padStart(7) + (nofPercent + "%").padStart(5) + - BYTES(ownBytes, this.bytesTotal).padStart(10); + BYTES(ownBytes, this.bytesTotal).padStart(16); log((` - ${name}`).padEnd(20) + value); this.metrics.set(name + "-bytes", ownBytes); this.metrics.set(name + "-count", funktions.length); @@ -355,22 +353,24 @@ class Script extends CompilationUnit { log(' - details: ' + 'isEval=' + this.isEval + ' deserialized=' + this.isDeserialized + ' streamed=' + this.isStreamingCompiled); + log(" Category Count Bytes"); info("scripts", this.getScripts()); info("functions", all); - info("toplevel fn", all.filter(each => each.isToplevel())); + info("toplevel fns", all.filter(each => each.isToplevel())); info('preparsed', all.filter(each => each.preparseDuration > 0)); info('fully parsed', all.filter(each => each.parseDuration > 0)); // info("fn parsed", all.filter(each => each.parse2Duration > 0)); // info("resolved", all.filter(each => each.resolutionDuration > 0)); info("executed", all.filter(each => each.executionTimestamp > 0)); - info('forEval', all.filter(each => each.isEval)); + info('eval', all.filter(each => each.isEval)); info("lazy compiled", all.filter(each => each.lazyCompileTimestamp > 0)); info("eager compiled", all.filter(each => each.compileTimestamp > 0)); info("baseline", all.filter(each => each.baselineTimestamp > 0)); info("optimized", all.filter(each => each.optimizeTimestamp > 0)); + log(" Cost split: executed vs non-executed functions, max = longest single event"); const costs = [ ['parse', each => each.parseDuration], ['preparse', each => each.preparseDuration], @@ -500,7 +500,6 @@ class Script extends CompilationUnit { // [time-delta, time+delta] range. return this.funktions.filter( funktion => funktion.didMetricChange(time, delta, metric)); - return result; } } @@ -552,7 +551,7 @@ class NestingDistribution { } print() { - console.log(this.toString()) + console.log(this.toString()); } toString() { @@ -565,12 +564,12 @@ class NestingDistribution { let percent1 = this.accumulator[1]; let percent2plus = this.accumulator.slice(2) .reduce((sum, each) => sum + each, 0); - return " - nesting level: " + + return " - fn nesting level: " + ' avg=' + formatNumber(this.avg) + ' l0=' + PERCENT(percent0, this.totalBytes) + ' l1=' + PERCENT(percent1, this.totalBytes) + ' l2+=' + PERCENT(percent2plus, this.totalBytes) + - ' distribution=[' + accString + ']'; + ' nesting-histogram=[' + accString + ']'; } @@ -581,7 +580,7 @@ class ExecutionCost { constructor(prefix, funktions, time_fn) { this.prefix = prefix; // Time spent on executed functions. - this.executedCost = 0 + this.executedCost = 0; // Time spent on not executed functions. this.nonExecutedCost = 0; this.maxDuration = 0; @@ -604,9 +603,9 @@ class ExecutionCost { toString() { return ` - ${this.prefix}-time:`.padEnd(24) + - ` executed=${formatNumber(this.executedCost)}ms`.padEnd(20) + - ` non-executed=${formatNumber(this.nonExecutedCost)}ms`.padEnd(24) + - ` max=${formatNumber(this.maxDuration)}ms`; + ` Σ executed=${TIME(this.executedCost)}`.padEnd(20) + + ` Σ non-executed=${TIME(this.nonExecutedCost)}`.padEnd(24) + + ` max=${TIME(this.maxDuration)}`; } setMetrics(dict) { @@ -625,7 +624,8 @@ class Funktion extends CompilationUnit { if (end < start) throw 'invalid start end positions'; } else { if (end <= 0) throw `invalid end position: ${end}`; - if (end <= start) throw 'invalid start end positions'; + if (end < start) throw 'invalid start end positions'; + if (end == start) console.error("Possibly invalid start/end position") } this.name = name; @@ -738,7 +738,7 @@ function toTimestamp(microseconds) { function startOf(timestamp, time) { let result = toTimestamp(timestamp) - time; - if (result < 0) throw "start timestamp cannnot be negative"; + if (result < 0) throw "start timestamp cannot be negative"; return result; } @@ -795,9 +795,9 @@ export class ParseProcessor extends LogReader { 'preparse-no-resolution': this.processPreparseNoResolution.bind(this), 'preparse-resolution': this.processPreparseResolution.bind(this), 'first-execution': this.processFirstExecution.bind(this), - 'compile-lazy': this.processCompileLazy.bind(this), - 'compile': this.processCompile.bind(this), - 'compile-eval': this.processCompileEval.bind(this), + 'interpreter-lazy': this.processCompileLazy.bind(this), + 'interpreter': this.processCompile.bind(this), + 'interpreter-eval': this.processCompileEval.bind(this), 'baseline': this.processBaselineLazy.bind(this), 'baseline-lazy': this.processBaselineLazy.bind(this), 'optimize-lazy': this.processOptimizeLazy.bind(this), @@ -819,17 +819,17 @@ export class ParseProcessor extends LogReader { this.idToScript.forEach(script => script.print()); } - processString(string) { - this.processLogChunk(string); + async processString(string) { + await this.processLogChunk(string); this.postProcess(); } - processLogFile(fileName) { + async processLogFile(fileName) { this.collectEntries = true this.lastLogFileName_ = fileName; let line; while (line = readline()) { - this.processLogLine(line); + await this.processLogLine(line); } this.postProcess(); } @@ -838,9 +838,14 @@ export class ParseProcessor extends LogReader { this.scripts = Array.from(this.idToScript.values()) .filter(each => !each.isNative); + if (this.scripts.length == 0) { + console.error("Could not find any scripts!"); + return false; + } + this.scripts.forEach(script => { script.finalize(); - script.calculateMetrics(false) + script.calculateMetrics(false); }); this.scripts.forEach(script => this.totalScript.addAllFunktions(script)); @@ -905,7 +910,7 @@ export class ParseProcessor extends LogReader { let results = []; this.idToScript.forEach(script => { script.forEach(funktion => { - if (funktion.startPostion == start && funktion.endPosition == end) { + if (funktion.startPosition == start && funktion.endPosition == end) { results.push(funktion); } });