[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 <victorgomes@chromium.org>
Commit-Queue: Camillo Bruni <cbruni@chromium.org>
Cr-Commit-Position: refs/heads/main@{#82206}
This commit is contained in:
Camillo Bruni 2022-08-04 12:33:53 +02:00 committed by V8 LUCI CQ
parent a44803dce6
commit 53c3e10482
3 changed files with 50 additions and 40 deletions

View File

@ -23,16 +23,21 @@ export function formatMicroSeconds(micro) {
return (micro * kMicro2Milli).toFixed(1) + 'ms'; return (micro * kMicro2Milli).toFixed(1) + 'ms';
} }
export function formatDurationMicros(micros, secondsDigits = 3) { export function formatDurationMicros(micros, digits = 3) {
return formatDurationMillis(micros * kMicro2Milli, secondsDigits); 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 < 1000) {
if (millis < 1) { 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; let seconds = millis / 1000;
const hours = Math.floor(seconds / 3600); const hours = Math.floor(seconds / 3600);
@ -41,7 +46,7 @@ export function formatDurationMillis(millis, secondsDigits = 3) {
let buffer = ''; let buffer = '';
if (hours > 0) buffer += hours + 'h '; if (hours > 0) buffer += hours + 'h ';
if (hours > 0 || minutes > 0) buffer += minutes + 'm '; if (hours > 0 || minutes > 0) buffer += minutes + 'm ';
buffer += seconds.toFixed(secondsDigits) + 's'; buffer += seconds.toFixed(digits) + 's';
return buffer; return buffer;
} }

View File

@ -130,11 +130,11 @@ document.loadFile = function() {
let file = files[0]; let file = files[0];
let reader = new FileReader(); let reader = new FileReader();
reader.onload = function(evt) { reader.onload = async function(evt) {
const kTimerName = 'parse log file'; const kTimerName = 'parse log file';
console.time(kTimerName); console.time(kTimerName);
let parseProcessor = new ParseProcessor(); let parseProcessor = new ParseProcessor();
parseProcessor.processString(this.result); await parseProcessor.processString(this.result);
console.timeEnd(kTimerName); console.timeEnd(kTimerName);
renderParseResults(parseProcessor); renderParseResults(parseProcessor);
document.parseProcessor = parseProcessor; document.parseProcessor = parseProcessor;

View File

@ -3,6 +3,7 @@
// found in the LICENSE file. // found in the LICENSE file.
import { LogReader, parseString } from "./logreader.mjs"; import { LogReader, parseString } from "./logreader.mjs";
import { BaseArgumentsProcessor } from "./arguments.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) { export function BYTES(bytes, total) {
let units = ['B ', 'kB', 'mB', 'gB']; let result = formatBytes(bytes)
let unitIndex = 0;
let value = bytes;
while (value > 1000 && unitIndex < units.length) {
value /= 1000;
unitIndex++;
}
let result = formatNumber(value).padStart(10) + ' ' + units[unitIndex];
if (total !== undefined && total != 0) { if (total !== undefined && total != 0) {
result += PERCENT(bytes, total).padStart(5); result += PERCENT(bytes, total).padStart(5);
} }
return result; return result;
} }
export function TIME(millis) {
return formatMillis(millis, 1);
}
export function PERCENT(value, total) { export function PERCENT(value, total) {
return Math.round(value / total * 100) + "%"; return Math.round(value / total * 100) + "%";
} }
@ -264,7 +262,7 @@ class Script extends CompilationUnit {
this.maxNestingLevel = maxNesting; this.maxNestingLevel = maxNesting;
// Initialize sizes. // Initialize sizes.
if (!this.ownBytes === -1) throw 'Invalid state'; if (this.ownBytes === -1) console.error('Invalid ownBytes');
if (this.funktions.length == 0) { if (this.funktions.length == 0) {
this.bytesTotal = this.ownBytes = 0; this.bytesTotal = this.ownBytes = 0;
return; return;
@ -340,9 +338,9 @@ class Script extends CompilationUnit {
let info = (name, funktions) => { let info = (name, funktions) => {
let ownBytes = ownBytesSum(funktions); let ownBytes = ownBytesSum(funktions);
let nofPercent = Math.round(funktions.length / nofFunktions * 100); let nofPercent = Math.round(funktions.length / nofFunktions * 100);
let value = (funktions.length + "").padStart(6) + let value = (funktions.length + "#").padStart(7) +
(nofPercent + "%").padStart(5) + (nofPercent + "%").padStart(5) +
BYTES(ownBytes, this.bytesTotal).padStart(10); BYTES(ownBytes, this.bytesTotal).padStart(16);
log((` - ${name}`).padEnd(20) + value); log((` - ${name}`).padEnd(20) + value);
this.metrics.set(name + "-bytes", ownBytes); this.metrics.set(name + "-bytes", ownBytes);
this.metrics.set(name + "-count", funktions.length); this.metrics.set(name + "-count", funktions.length);
@ -355,22 +353,24 @@ class Script extends CompilationUnit {
log(' - details: ' + log(' - details: ' +
'isEval=' + this.isEval + ' deserialized=' + this.isDeserialized + 'isEval=' + this.isEval + ' deserialized=' + this.isDeserialized +
' streamed=' + this.isStreamingCompiled); ' streamed=' + this.isStreamingCompiled);
log(" Category Count Bytes");
info("scripts", this.getScripts()); info("scripts", this.getScripts());
info("functions", all); 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('preparsed', all.filter(each => each.preparseDuration > 0));
info('fully parsed', all.filter(each => each.parseDuration > 0)); info('fully parsed', all.filter(each => each.parseDuration > 0));
// info("fn parsed", all.filter(each => each.parse2Duration > 0)); // info("fn parsed", all.filter(each => each.parse2Duration > 0));
// info("resolved", all.filter(each => each.resolutionDuration > 0)); // info("resolved", all.filter(each => each.resolutionDuration > 0));
info("executed", all.filter(each => each.executionTimestamp > 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("lazy compiled", all.filter(each => each.lazyCompileTimestamp > 0));
info("eager compiled", all.filter(each => each.compileTimestamp > 0)); info("eager compiled", all.filter(each => each.compileTimestamp > 0));
info("baseline", all.filter(each => each.baselineTimestamp > 0)); info("baseline", all.filter(each => each.baselineTimestamp > 0));
info("optimized", all.filter(each => each.optimizeTimestamp > 0)); info("optimized", all.filter(each => each.optimizeTimestamp > 0));
log(" Cost split: executed vs non-executed functions, max = longest single event");
const costs = [ const costs = [
['parse', each => each.parseDuration], ['parse', each => each.parseDuration],
['preparse', each => each.preparseDuration], ['preparse', each => each.preparseDuration],
@ -500,7 +500,6 @@ class Script extends CompilationUnit {
// [time-delta, time+delta] range. // [time-delta, time+delta] range.
return this.funktions.filter( return this.funktions.filter(
funktion => funktion.didMetricChange(time, delta, metric)); funktion => funktion.didMetricChange(time, delta, metric));
return result;
} }
} }
@ -552,7 +551,7 @@ class NestingDistribution {
} }
print() { print() {
console.log(this.toString()) console.log(this.toString());
} }
toString() { toString() {
@ -565,12 +564,12 @@ class NestingDistribution {
let percent1 = this.accumulator[1]; let percent1 = this.accumulator[1];
let percent2plus = this.accumulator.slice(2) let percent2plus = this.accumulator.slice(2)
.reduce((sum, each) => sum + each, 0); .reduce((sum, each) => sum + each, 0);
return " - nesting level: " + return " - fn nesting level: " +
' avg=' + formatNumber(this.avg) + ' avg=' + formatNumber(this.avg) +
' l0=' + PERCENT(percent0, this.totalBytes) + ' l0=' + PERCENT(percent0, this.totalBytes) +
' l1=' + PERCENT(percent1, this.totalBytes) + ' l1=' + PERCENT(percent1, this.totalBytes) +
' l2+=' + PERCENT(percent2plus, this.totalBytes) + ' l2+=' + PERCENT(percent2plus, this.totalBytes) +
' distribution=[' + accString + ']'; ' nesting-histogram=[' + accString + ']';
} }
@ -581,7 +580,7 @@ class ExecutionCost {
constructor(prefix, funktions, time_fn) { constructor(prefix, funktions, time_fn) {
this.prefix = prefix; this.prefix = prefix;
// Time spent on executed functions. // Time spent on executed functions.
this.executedCost = 0 this.executedCost = 0;
// Time spent on not executed functions. // Time spent on not executed functions.
this.nonExecutedCost = 0; this.nonExecutedCost = 0;
this.maxDuration = 0; this.maxDuration = 0;
@ -604,9 +603,9 @@ class ExecutionCost {
toString() { toString() {
return ` - ${this.prefix}-time:`.padEnd(24) + return ` - ${this.prefix}-time:`.padEnd(24) +
` executed=${formatNumber(this.executedCost)}ms`.padEnd(20) + ` Σ executed=${TIME(this.executedCost)}`.padEnd(20) +
` non-executed=${formatNumber(this.nonExecutedCost)}ms`.padEnd(24) + ` Σ non-executed=${TIME(this.nonExecutedCost)}`.padEnd(24) +
` max=${formatNumber(this.maxDuration)}ms`; ` max=${TIME(this.maxDuration)}`;
} }
setMetrics(dict) { setMetrics(dict) {
@ -625,7 +624,8 @@ class Funktion extends CompilationUnit {
if (end < start) throw 'invalid start end positions'; if (end < start) throw 'invalid start end positions';
} else { } else {
if (end <= 0) throw `invalid end position: ${end}`; 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; this.name = name;
@ -738,7 +738,7 @@ function toTimestamp(microseconds) {
function startOf(timestamp, time) { function startOf(timestamp, time) {
let result = toTimestamp(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; return result;
} }
@ -795,9 +795,9 @@ export class ParseProcessor extends LogReader {
'preparse-no-resolution': this.processPreparseNoResolution.bind(this), 'preparse-no-resolution': this.processPreparseNoResolution.bind(this),
'preparse-resolution': this.processPreparseResolution.bind(this), 'preparse-resolution': this.processPreparseResolution.bind(this),
'first-execution': this.processFirstExecution.bind(this), 'first-execution': this.processFirstExecution.bind(this),
'compile-lazy': this.processCompileLazy.bind(this), 'interpreter-lazy': this.processCompileLazy.bind(this),
'compile': this.processCompile.bind(this), 'interpreter': this.processCompile.bind(this),
'compile-eval': this.processCompileEval.bind(this), 'interpreter-eval': this.processCompileEval.bind(this),
'baseline': this.processBaselineLazy.bind(this), 'baseline': this.processBaselineLazy.bind(this),
'baseline-lazy': this.processBaselineLazy.bind(this), 'baseline-lazy': this.processBaselineLazy.bind(this),
'optimize-lazy': this.processOptimizeLazy.bind(this), 'optimize-lazy': this.processOptimizeLazy.bind(this),
@ -819,17 +819,17 @@ export class ParseProcessor extends LogReader {
this.idToScript.forEach(script => script.print()); this.idToScript.forEach(script => script.print());
} }
processString(string) { async processString(string) {
this.processLogChunk(string); await this.processLogChunk(string);
this.postProcess(); this.postProcess();
} }
processLogFile(fileName) { async processLogFile(fileName) {
this.collectEntries = true this.collectEntries = true
this.lastLogFileName_ = fileName; this.lastLogFileName_ = fileName;
let line; let line;
while (line = readline()) { while (line = readline()) {
this.processLogLine(line); await this.processLogLine(line);
} }
this.postProcess(); this.postProcess();
} }
@ -838,9 +838,14 @@ export class ParseProcessor extends LogReader {
this.scripts = Array.from(this.idToScript.values()) this.scripts = Array.from(this.idToScript.values())
.filter(each => !each.isNative); .filter(each => !each.isNative);
if (this.scripts.length == 0) {
console.error("Could not find any scripts!");
return false;
}
this.scripts.forEach(script => { this.scripts.forEach(script => {
script.finalize(); script.finalize();
script.calculateMetrics(false) script.calculateMetrics(false);
}); });
this.scripts.forEach(script => this.totalScript.addAllFunktions(script)); this.scripts.forEach(script => this.totalScript.addAllFunktions(script));
@ -905,7 +910,7 @@ export class ParseProcessor extends LogReader {
let results = []; let results = [];
this.idToScript.forEach(script => { this.idToScript.forEach(script => {
script.forEach(funktion => { script.forEach(funktion => {
if (funktion.startPostion == start && funktion.endPosition == end) { if (funktion.startPosition == start && funktion.endPosition == end) {
results.push(funktion); results.push(funktion);
} }
}); });