Skip to content

Commit

Permalink
Expand the Tracer output to include a manifset of the node types in t…
Browse files Browse the repository at this point in the history 
…he AST when compilation begins.

-------------
Created by MOE: https://github.com/google/moe
MOE_MIGRATED_REVID=258806366
  • Loading branch information
@nreid260 @lauraharker
nreid260 authored and lauraharker committed Jul 19, 2019
1 parent f0e7813 commit 33a97c3
Show file tree
Hide file tree
Showing 2 changed files with 143 additions and 62 deletions.
83 changes: 58 additions & 25 deletions src/com/google/javascript/jscomp/PerformanceTracker.java
View file
Expand Up @@ -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;
Expand Down Expand Up @@ -85,7 +87,9 @@ public final class PerformanceTracker {
private final Deque<Stats> currentPass = new ArrayDeque<>();

/** Cumulative stats for each compiler pass. */
private ImmutableMap<String, Stats> summary;
private ImmutableMap<String, Stats> passSummary;

private ImmutableMultiset<Token> astManifest;

/** Stats a single run of a compiler pass. */
private final List<Stats> log = new ArrayList<>();
Expand Down Expand Up @@ -162,6 +166,9 @@ void recordPassStop(String passName, long runtime) {
}

private void recordParsingStop(Stats logStats) {
if (tracksAstManifest()) {
populateAstManifest();
}
recordInputCount();
if (!tracksAstSize()) {
return;
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -285,19 +296,19 @@ int getLoopRuns() {

public ImmutableMap<String, Stats> 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<String, Stats> entry : this.summary.entrySet()) {
for (Entry<String, Stats> entry : this.passSummary.entrySet()) {
Stats stats = entry.getValue();
this.passesRuntime += stats.runtime;
this.maxMem = Math.max(this.maxMem, stats.allocMem);
Expand All @@ -316,15 +327,15 @@ private void calcTotalStats() {
checkState(!tracksGzSize() || this.initGzCodeSize == this.gzDiff + this.gzCodeSize);
}

private void populateSummary() {
HashMap<String, Stats> tmpSummary = new HashMap<>();
private void populatePassSummary() {
HashMap<String, Stats> 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);
Expand All @@ -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<Token> builder = ImmutableMultiset.builder();
NodeUtil.visitPreOrder(this.jsRoot, (n) -> builder.add(n.getToken()));
this.astManifest = builder.build();
}

/**
Expand Down Expand Up @@ -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(
Expand All @@ -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
Expand Down
122 changes: 85 additions & 37 deletions test/com/google/javascript/jscomp/PerformanceTrackerTest.java
View file
Expand Up @@ -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;
Expand Down Expand Up @@ -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);
}
}

0 comments on commit 33a97c3

Please sign in to comment.