From 33a97c3ba00824f89ee29cb4f01dd872e8ad12cc Mon Sep 17 00:00:00 2001 From: nickreid Date: Thu, 18 Jul 2019 11:07:22 -0700 Subject: [PATCH] Expand the Tracer output to include a manifset of the node types in the AST when compilation begins. ------------- Created by MOE: https://github.com/google/moe MOE_MIGRATED_REVID=258806366 --- .../javascript/jscomp/PerformanceTracker.java | 83 ++++++++---- .../jscomp/PerformanceTrackerTest.java | 122 ++++++++++++------ 2 files changed, 143 insertions(+), 62 deletions(-) diff --git a/src/com/google/javascript/jscomp/PerformanceTracker.java b/src/com/google/javascript/jscomp/PerformanceTracker.java index ca7371b1b2e..492d65cce14 100644 --- a/src/com/google/javascript/jscomp/PerformanceTracker.java +++ b/src/com/google/javascript/jscomp/PerformanceTracker.java @@ -21,10 +21,12 @@ import com.google.common.annotations.VisibleForTesting; import com.google.common.collect.ImmutableMap; +import com.google.common.collect.ImmutableMultiset; import com.google.javascript.jscomp.CompilerOptions.TracerMode; import com.google.javascript.jscomp.parsing.parser.util.format.SimpleFormat; import com.google.javascript.rhino.Node; import com.google.javascript.rhino.StaticSourceFile; +import com.google.javascript.rhino.Token; import java.io.FilterOutputStream; import java.io.IOException; import java.io.PrintStream; @@ -85,7 +87,9 @@ public final class PerformanceTracker { private final Deque currentPass = new ArrayDeque<>(); /** Cumulative stats for each compiler pass. */ - private ImmutableMap summary; + private ImmutableMap passSummary; + + private ImmutableMultiset astManifest; /** Stats a single run of a compiler pass. */ private final List log = new ArrayList<>(); @@ -162,6 +166,9 @@ void recordPassStop(String passName, long runtime) { } private void recordParsingStop(Stats logStats) { + if (tracksAstManifest()) { + populateAstManifest(); + } recordInputCount(); if (!tracksAstSize()) { return; @@ -239,6 +246,10 @@ public boolean tracksAstSize() { return this.mode != TracerMode.TIMING_ONLY; } + public boolean tracksAstManifest() { + return this.mode.isOn(); + } + public int getRuntime() { calcTotalStats(); return this.passesRuntime; @@ -285,19 +296,19 @@ int getLoopRuns() { public ImmutableMap getStats() { calcTotalStats(); - return this.summary; + return this.passSummary; } private void calcTotalStats() { // This method only does work the first time it is called - if (this.summary != null) { + if (this.passSummary != null) { return; } this.endTime = System.currentTimeMillis(); - populateSummary(); + populatePassSummary(); - for (Entry entry : this.summary.entrySet()) { + for (Entry entry : this.passSummary.entrySet()) { Stats stats = entry.getValue(); this.passesRuntime += stats.runtime; this.maxMem = Math.max(this.maxMem, stats.allocMem); @@ -316,15 +327,15 @@ private void calcTotalStats() { checkState(!tracksGzSize() || this.initGzCodeSize == this.gzDiff + this.gzCodeSize); } - private void populateSummary() { - HashMap tmpSummary = new HashMap<>(); + private void populatePassSummary() { + HashMap tmpPassSummary = new HashMap<>(); for (Stats logStat : this.log) { String passName = logStat.pass; - Stats entry = tmpSummary.get(passName); + Stats entry = tmpPassSummary.get(passName); if (entry == null) { entry = new Stats(passName, logStat.isOneTime); - tmpSummary.put(passName, entry); + tmpPassSummary.put(passName, entry); } entry.runtime += logStat.runtime; entry.allocMem = Math.max(entry.allocMem, logStat.allocMem); @@ -333,12 +344,22 @@ private void populateSummary() { entry.astDiff += logStat.astDiff; entry.diff += logStat.diff; entry.gzDiff += logStat.gzDiff; - // We don't populate the size fields in the summary stats. + // We don't populate the size fields in the passSummary stats. // We used to put the size after the last time a pass was run, but that is // a pretty meaningless thing to measure. } - this.summary = ImmutableMap.copyOf(tmpSummary); + this.passSummary = ImmutableMap.copyOf(tmpPassSummary); + } + + private void populateAstManifest() { + if (this.astManifest != null) { + return; + } + + ImmutableMultiset.Builder builder = ImmutableMultiset.builder(); + NodeUtil.visitPreOrder(this.jsRoot, (n) -> builder.add(n.getToken())); + this.astManifest = builder.build(); } /** @@ -383,24 +404,24 @@ public void outputTracerReport(PrintStream output) { "", "Summary:", "pass,runtime,allocMem,runs,changingRuns,astReduction,reduction,gzReduction")); - this.summary.entrySet().stream() + this.passSummary.entrySet().stream() .sorted((e1, e2) -> Long.compare(e1.getValue().runtime, e2.getValue().runtime)) - .forEach( + .map( (entry) -> { String key = entry.getKey(); Stats stats = entry.getValue(); - output.print( - SimpleFormat.format( - "%s,%d,%d,%d,%d,%d,%d,%d\n", - key, - stats.runtime, - stats.allocMem, - stats.runs, - stats.changes, - stats.astDiff, - stats.diff, - stats.gzDiff)); - }); + return SimpleFormat.format( + "%s,%d,%d,%d,%d,%d,%d,%d", + key, + stats.runtime, + stats.allocMem, + stats.runs, + stats.changes, + stats.astDiff, + stats.diff, + stats.gzDiff); + }) + .forEach(output::println); output.println( lines( @@ -423,6 +444,18 @@ public void outputTracerReport(PrintStream output) { stats.gzSize)); } + if (this.astManifest != null) { + output.println( + lines( + "", // + "Input AST Manifest:", + "token,count")); + this.astManifest.entrySet().stream() + .map((e) -> SimpleFormat.format("%s,%d", e.getElement(), e.getCount())) + .sorted() + .forEach(output::println); + } + output.println(); // this.output can be System.out, so don't close it to not lose subsequent diff --git a/test/com/google/javascript/jscomp/PerformanceTrackerTest.java b/test/com/google/javascript/jscomp/PerformanceTrackerTest.java index d7570aeb0ff..630580ad312 100644 --- a/test/com/google/javascript/jscomp/PerformanceTrackerTest.java +++ b/test/com/google/javascript/jscomp/PerformanceTrackerTest.java @@ -18,10 +18,10 @@ import static com.google.common.truth.Truth.assertThat; -import com.google.common.base.Joiner; import com.google.common.collect.ImmutableMap; import com.google.javascript.jscomp.CompilerOptions.TracerMode; import com.google.javascript.jscomp.PerformanceTracker.Stats; +import com.google.javascript.rhino.IR; import com.google.javascript.rhino.Node; import com.google.javascript.rhino.Token; import java.io.ByteArrayOutputStream; @@ -106,47 +106,95 @@ public void testStatsCalculation() { assertThat(st.changes).isEqualTo(0); } + @Test + public void testAstSummaryAndFormat() { + // Given + Node main = + IR.root( + IR.script( + IR.block( + IR.block( + IR.exprResult( // + IR.hook(IR.string("a"), IR.string("b"), IR.string("c")))), + IR.function(IR.name("name"), IR.paramList(), IR.block())))); + PerformanceTracker tracker = + new PerformanceTracker(emptyExternRoot, main, TracerMode.TIMING_ONLY); + + // When + tracker.recordPassStart(PassNames.PARSE_INPUTS, true); + tracker.recordPassStop(PassNames.PARSE_INPUTS, 0); // This is what triggers the counting. + String report = extractReport(tracker); + + // Then + assertThat(report) + .containsMatch( + Pattern.compile( + lines( + "Input AST Manifest:", + "token,count", + "BLOCK,3", + "EXPR_RESULT,1", + "FUNCTION,1", + "HOOK,1", + "NAME,1", + "PARAM_LIST,1", + "ROOT,1", + "SCRIPT,1", + "STRING,3"), + Pattern.DOTALL)); + } + @Test public void testOutputFormat() { + PerformanceTracker tracker = + new PerformanceTracker(emptyExternRoot, emptyJsRoot, TracerMode.ALL); + String report = extractReport(tracker); + Pattern p = + Pattern.compile( + lines( + ".*TOTAL:", + "Start time\\(ms\\): [0-9]+", + "End time\\(ms\\): [0-9]+", + "Wall time\\(ms\\): [0-9]+", + "Passes runtime\\(ms\\): [0-9]+", + "Max mem usage \\(measured after each pass\\)\\(MB\\): -?[0-9]+", + "#Runs: [0-9]+", + "#Changing runs: [0-9]+", + "#Loopable runs: [0-9]+", + "#Changing loopable runs: [0-9]+", + "Estimated AST reduction\\(#nodes\\): [0-9]+", + "Estimated Reduction\\(bytes\\): [0-9]+", + "Estimated GzReduction\\(bytes\\): [0-9]+", + "Estimated AST size\\(#nodes\\): -?[0-9]+", + "Estimated Size\\(bytes\\): -?[0-9]+", + "Estimated GzSize\\(bytes\\): -?[0-9]+", + "", + "Inputs:", + "JS lines: [0-9]+", + "JS sources: [0-9]+", + "Extern lines: [0-9]+", + "Extern sources: [0-9]+", + "", + "Summary:", + "pass,runtime,allocMem,runs,changingRuns,astReduction,reduction,gzReduction", + "", + "Log:", + "pass,runtime,allocMem,codeChanged,astReduction,reduction,gzReduction,astSize,size,gzSize", + ".*"), + Pattern.DOTALL); + + assertThat(report).matches(p); + } + + private static final String extractReport(PerformanceTracker tracker) { ByteArrayOutputStream output = new ByteArrayOutputStream(); try (PrintStream outstream = new PrintStream(output)) { - PerformanceTracker tracker = - new PerformanceTracker(emptyExternRoot, emptyJsRoot, TracerMode.ALL); tracker.outputTracerReport(outstream); } - Pattern p = Pattern.compile(Joiner.on("\n").join( - ".*TOTAL:", - "Start time\\(ms\\): [0-9]+", - "End time\\(ms\\): [0-9]+", - "Wall time\\(ms\\): [0-9]+", - "Passes runtime\\(ms\\): [0-9]+", - "Max mem usage \\(measured after each pass\\)\\(MB\\): -?[0-9]+", - "#Runs: [0-9]+", - "#Changing runs: [0-9]+", - "#Loopable runs: [0-9]+", - "#Changing loopable runs: [0-9]+", - "Estimated AST reduction\\(#nodes\\): [0-9]+", - "Estimated Reduction\\(bytes\\): [0-9]+", - "Estimated GzReduction\\(bytes\\): [0-9]+", - "Estimated AST size\\(#nodes\\): -?[0-9]+", - "Estimated Size\\(bytes\\): -?[0-9]+", - "Estimated GzSize\\(bytes\\): -?[0-9]+", - "", - "Inputs:", - "JS lines: [0-9]+", - "JS sources: [0-9]+", - "Extern lines: [0-9]+", - "Extern sources: [0-9]+", - "", - "Summary:", - "pass,runtime,allocMem,runs,changingRuns,astReduction,reduction,gzReduction", - "", - "Log:", - "pass,runtime,allocMem,codeChanged,astReduction,reduction,gzReduction,astSize,size,gzSize", - "", - ".*"), - Pattern.DOTALL); - String outputString = output.toString(); - assertThat(outputString).matches(p); + return output.toString(); + } + + private static String lines(String... lines) { + return String.join("\n", lines); } }