Add memory-usage stats (collected after each pass) to PerformanceTrac…

…ker.

Sample output:

After pass renameLabels: 	 Used mem(MB): 177	 Free mem(MB): 308	 Total mem(MB): 485
After pass latePeepholeOptimizations: 	 Used mem(MB): 201	 Free mem(MB): 284	 Total mem(MB): 485
After pass stripSideEffectProtection: 	 Used mem(MB): 215	 Free mem(MB): 270	 Total mem(MB): 485
After pass sanityCheckAst: 	 Used mem(MB): 215	 Free mem(MB): 270	 Total mem(MB): 485
After pass sanityCheckVars: 	 Used mem(MB): 215	 Free mem(MB): 270	 Total mem(MB): 485

TOTAL:
Runtime(ms): 19042
Mem usage after each pass(MB): 179.14 +/- 37.46
-------------
Created by MOE: https://github.com/google/moe
MOE_MIGRATED_REVID=126164670

src/com/google/javascript/jscomp/Compiler.java

@@ -256,7 +256,7 @@ public Compiler() {
    */
   public Compiler(PrintStream stream) {
     addChangeHandler(recentChange);
-    outStream = stream;
+    this.outStream = stream;
   }
 
   /**
@@ -301,12 +301,12 @@ public void initOptions(CompilerOptions options) {
     this.options = options;
     this.languageMode = options.getLanguageIn();
     if (errorManager == null) {
-      if (outStream == null) {
+      if (this.outStream == null) {
         setErrorManager(
             new LoggerErrorManager(createMessageFormatter(), logger));
       } else {
         PrintStreamErrorManager printer =
-            new PrintStreamErrorManager(createMessageFormatter(), outStream);
+            new PrintStreamErrorManager(createMessageFormatter(), this.outStream);
         printer.setSummaryDetailLevel(options.summaryDetailLevel);
         setErrorManager(printer);
       }
@@ -738,7 +738,7 @@ private void compileInternal() {
     setProgress(1.0, "recordFunctionInformation");
 
     if (tracker != null) {
-      tracker.outputTracerReport(outStream == null ? System.out : outStream);
+      tracker.outputTracerReport();
     }
   }
 
@@ -1361,7 +1361,7 @@ Node parseInputs() {
     jsRoot.detachChildren();
 
     if (options.tracer.isOn()) {
-      tracker = new PerformanceTracker(jsRoot, options.tracer);
+      tracker = new PerformanceTracker(jsRoot, options.tracer, this.outStream);
       addChangeHandler(tracker.getCodeChangeHandler());
     }
 

src/com/google/javascript/jscomp/PerformanceTracker.java

@@ -54,6 +54,9 @@ public final class PerformanceTracker {
 
   private static final int DEFAULT_WHEN_SIZE_UNTRACKED = -1;
 
+  private final PrintStream printStream;
+  private final OutputStreamWriter output;
+
   private final Node jsRoot;
   private final boolean trackSize;
   private final boolean trackGzSize;
@@ -70,6 +73,8 @@ public final class PerformanceTracker {
   private int changes = 0;
   private int loopRuns = 0;
   private int loopChanges = 0;
+  // An approximation of how many MBs are allocated after each compiler pass
+  private ArrayList<Integer> allocsInMB = new ArrayList<>();
 
   // The following fields for tracking size changes are just estimates.
   // They do not take into account preserved license blocks, newline padding,
@@ -91,8 +96,10 @@ public final class PerformanceTracker {
   /** Stats for each run of a compiler pass. */
   private final List<Stats> log = new ArrayList<>();
 
-  PerformanceTracker(Node jsRoot, TracerMode mode) {
+  PerformanceTracker(Node jsRoot, TracerMode mode, PrintStream printStream) {
     this.jsRoot = jsRoot;
+    this.printStream = printStream == null ? System.out : printStream;
+    this.output = new OutputStreamWriter(this.printStream, UTF_8);
     switch (mode) {
       case TIMING_ONLY:
         this.trackSize = false;
@@ -138,6 +145,8 @@ void recordPassStart(String passName, boolean isOneTime) {
    * @param runtime execution time in milliseconds
    */
   void recordPassStop(String passName, long runtime) {
+    writeMemStats(passName);
+
     Stats logStats = currentPass.pop();
     Preconditions.checkState(passName.equals(logStats.pass));
 
@@ -191,6 +200,28 @@ void recordPassStop(String passName, long runtime) {
     }
   }
 
+  private int bytesToMB(long bytes) {
+    return (int) (bytes / (1024 * 1024));
+  }
+
+  private void writeMemStats(String passName) {
+    try {
+      Runtime javaRuntime = Runtime.getRuntime();
+      int totalMem = bytesToMB(javaRuntime.totalMemory());
+      int freeMem = bytesToMB(javaRuntime.freeMemory());
+      int allocMem = totalMem - freeMem;
+      this.allocsInMB.add(allocMem);
+      this.output.write(
+          "After pass " + passName + ": "
+          + "\t Used mem(MB): " + allocMem
+          + "\t Free mem(MB): " + freeMem
+          + "\t Total mem(MB): " + totalMem + "\n");
+      this.output.flush();
+    } catch (IOException e) {
+      throw new RuntimeException("Failed to write statistics to output.", e);
+    }
+  }
+
   public boolean tracksSize() {
     return trackSize;
   }
@@ -243,6 +274,31 @@ public ImmutableMap<String, Stats> getStats() {
     return summaryCopy;
   }
 
+  private double meanMemUsed() {
+    double size = this.allocsInMB.size();
+    if (size == 0) {
+      return 0;
+    }
+    double sum = 0.0;
+    for (int i = 0; i < size; i++) {
+      sum += this.allocsInMB.get(i);
+    }
+    return sum / size;
+  }
+
+  private double usedMemStandardDeviation(double meanMemUsed) {
+    double size = this.allocsInMB.size();
+    if (size == 0) {
+      return 0;
+    }
+    double sum = 0.0;
+    for (int i = 0; i < size; i++) {
+      sum += Math.pow(this.allocsInMB.get(i) - meanMemUsed, 2);
+    }
+    double variance = sum / size;
+    return Math.sqrt(variance);
+  }
+
   private void calcTotalStats() {
     // This method only does work the first time it's called
     if (summaryCopy != null) {
@@ -270,9 +326,8 @@ private void calcTotalStats() {
    * Prints a summary, which contains aggregate stats for all runs of each pass
    * and a log, which contains stats for each individual run.
    */
-  public void outputTracerReport(PrintStream pstr) {
-    JvmMetrics.maybeWriteJvmMetrics(pstr, "verbose:pretty:all");
-    OutputStreamWriter output = new OutputStreamWriter(pstr, UTF_8);
+  public void outputTracerReport() {
+    JvmMetrics.maybeWriteJvmMetrics(this.printStream, "verbose:pretty:all");
     try {
       calcTotalStats();
 
@@ -287,32 +342,36 @@ public int compare(Entry<String, Stats> e1, Entry<String, Stats> e2) {
             }
           });
 
-      output.write("Summary:\n" +
+      this.output.write("Summary:\n" +
           "pass,runtime,runs,changingRuns,reduction,gzReduction\n");
       for (Entry<String, Stats> entry : statEntries) {
         String key = entry.getKey();
         Stats stats = entry.getValue();
-        output.write(String.format("%s,%d,%d,%d,%d,%d\n", key, stats.runtime,
+        this.output.write(String.format("%s,%d,%d,%d,%d,%d\n", key, stats.runtime,
             stats.runs, stats.changes, stats.diff, stats.gzDiff));
       }
-      output.write("\nTOTAL:"
-          + "\nRuntime(ms): " + runtime + "\n#Runs: " + runs
+      double meanMem = meanMemUsed();
+      double stdDev = usedMemStandardDeviation(meanMem);
+      this.output.write("\nTOTAL:"
+          + "\nRuntime(ms): " + runtime
+          + String.format("\nMem usage after each pass(MB): %.2f +/- %.2f", meanMem, stdDev)
+          + "\n#Runs: " + runs
           + "\n#Changing runs: " + changes + "\n#Loopable runs: " + loopRuns
           + "\n#Changing loopable runs: " + loopChanges + "\nEstimated Reduction(bytes): " + diff
           + "\nEstimated GzReduction(bytes): " + gzDiff + "\nEstimated Size(bytes): " + codeSize
           + "\nEstimated GzSize(bytes): " + gzCodeSize + "\n\n");
 
-      output.write("Log:\n" +
+      this.output.write("Log:\n" +
           "pass,runtime,runs,changingRuns,reduction,gzReduction,size,gzSize\n");
       for (Stats stats : log) {
-        output.write(String.format("%s,%d,%d,%d,%d,%d,%d,%d\n",
+        this.output.write(String.format("%s,%d,%d,%d,%d,%d,%d,%d\n",
             stats.pass, stats.runtime, stats.runs, stats.changes,
             stats.diff, stats.gzDiff, stats.size, stats.gzSize));
       }
-      output.write("\n");
-      // output can be System.out, so don't close it to not lose subsequent
+      this.output.write("\n");
+      // this.output can be System.out, so don't close it to not lose subsequent
       // error messages. Flush to ensure that you will see the tracer report.
-      output.flush();
+      this.output.flush();
     } catch (IOException e) {
       throw new RuntimeException("Failed to write statistics to output.", e);
     }

src/com/google/javascript/jscomp/gwt/super/com/google/javascript/jscomp/PerformanceTracker.java

@@ -23,7 +23,7 @@
 
 /** GWT compatible no-op replacement for {@code PerformanceTracker} */
 public final class PerformanceTracker {
-  PerformanceTracker(Node jsRoot, TracerMode mode) {}
+  PerformanceTracker(Node jsRoot, TracerMode mode, PrintStream pstr) {}
 
   void recordPassStart(String passName, boolean isOneTime) {}
 
@@ -34,5 +34,5 @@ CodeChangeHandler getCodeChangeHandler() {
         "PerformanceTracker.getCodeChangeHandler not implemented");
   }
 
-  public void outputTracerReport(PrintStream pstr) {}
+  public void outputTracerReport() {}
 }

test/com/google/javascript/jscomp/PerformanceTrackerTest.java

@@ -38,7 +38,7 @@ public final class PerformanceTrackerTest extends TestCase {
 
   public void testStatsCalculation() {
     PerformanceTracker tracker =
-        new PerformanceTracker(emptyScript, TracerMode.ALL);
+        new PerformanceTracker(emptyScript, TracerMode.ALL, null);
     CodeChangeHandler handler = tracker.getCodeChangeHandler();
 
     // It's sufficient for this test to assume that a single run of any pass
@@ -101,29 +101,30 @@ public void testStatsCalculation() {
   }
 
   public void testOutputFormat() {
-    PerformanceTracker tracker =
-        new PerformanceTracker(emptyScript, TracerMode.ALL);
     ByteArrayOutputStream output = new ByteArrayOutputStream();
     PrintStream outstream = new PrintStream(output);
-    tracker.outputTracerReport(outstream);
+    PerformanceTracker tracker =
+        new PerformanceTracker(emptyScript, TracerMode.ALL, outstream);
+    tracker.outputTracerReport();
     outstream.close();
     Pattern p = Pattern.compile(
-        ".*Summary:\npass,runtime,runs,changingRuns,reduction,gzReduction" +
-        ".*TOTAL:" +
-        "\nRuntime\\(ms\\): [0-9]+" +
-        "\n#Runs: [0-9]+" +
-        "\n#Changing runs: [0-9]+" +
-        "\n#Loopable runs: [0-9]+" +
-        "\n#Changing loopable runs: [0-9]+" +
-        "\nEstimated Reduction\\(bytes\\): [0-9]+" +
-        "\nEstimated GzReduction\\(bytes\\): [0-9]+" +
-        "\nEstimated Size\\(bytes\\): -?[0-9]+" +
-        "\nEstimated GzSize\\(bytes\\): -?[0-9]+" +
-        "\n\nLog:\n" +
-        "pass,runtime,runs,changingRuns,reduction,gzReduction,size,gzSize.*",
+        ".*Summary:\npass,runtime,runs,changingRuns,reduction,gzReduction"
+        + ".*TOTAL:"
+        + "\nRuntime\\(ms\\): [0-9]+"
+        + "\nMem usage after each pass\\(MB\\): [0-9]+\\.[0-9]+ \\+/- [0-9]+\\.[0-9]+"
+        + "\n#Runs: [0-9]+"
+        + "\n#Changing runs: [0-9]+"
+        + "\n#Loopable runs: [0-9]+"
+        + "\n#Changing loopable runs: [0-9]+"
+        + "\nEstimated Reduction\\(bytes\\): [0-9]+"
+        + "\nEstimated GzReduction\\(bytes\\): [0-9]+"
+        + "\nEstimated Size\\(bytes\\): -?[0-9]+"
+        + "\nEstimated GzSize\\(bytes\\): -?[0-9]+"
+        + "\n\nLog:\n"
+        + "pass,runtime,runs,changingRuns,reduction,gzReduction,size,gzSize.*",
         Pattern.DOTALL);
     String outputString = output.toString();
     assertTrue("Unexpected output from PerformanceTracker:\n" + outputString,
         p.matcher(outputString).matches());
   }
-}
+}

test/com/google/javascript/jscomp/PhaseOptimizerTest.java

@@ -49,7 +49,7 @@ public void setUp() {
     dummyRoot.setIsSyntheticBlock(true);
     compiler = new Compiler();
     compiler.initCompilerOptionsIfTesting();
-    tracker = new PerformanceTracker(dummyRoot, TracerMode.TIMING_ONLY);
+    tracker = new PerformanceTracker(dummyRoot, TracerMode.TIMING_ONLY, null);
     optimizer = new PhaseOptimizer(compiler, tracker, null);
   }