Performance counters for tracking repetetive operations.
Rietveld: http://gwt-code-reviews.appspot.com/278801
Review by: spoon@google.com
git-svn-id: https://google-web-toolkit.googlecode.com/svn/trunk@7864 8db76d5a-ed1c-0410-87a9-c151d255dfc7
diff --git a/dev/core/src/com/google/gwt/dev/CompilePerms.java b/dev/core/src/com/google/gwt/dev/CompilePerms.java
index fb8c9e9..bfe2df3 100644
--- a/dev/core/src/com/google/gwt/dev/CompilePerms.java
+++ b/dev/core/src/com/google/gwt/dev/CompilePerms.java
@@ -25,6 +25,7 @@
import com.google.gwt.dev.jjs.PermutationResult;
import com.google.gwt.dev.jjs.UnifiedAst;
import com.google.gwt.dev.util.FileBackedObject;
+import com.google.gwt.dev.util.PerfCounter;
import com.google.gwt.dev.util.Util;
import com.google.gwt.dev.util.arg.ArgHandlerLocalWorkers;
import com.google.gwt.dev.util.arg.OptionLocalWorkers;
@@ -206,6 +207,7 @@
}
public static void main(String[] args) {
+ int exitCode = -1;
/*
* NOTE: main always exits with a call to System.exit to terminate any
* non-daemon threads that were started in Generators. Typically, this is to
@@ -221,11 +223,11 @@
};
if (CompileTaskRunner.runWithAppropriateLogger(options, task)) {
// Exit w/ success code.
- System.exit(0);
+ exitCode = 0;
}
}
- // Exit w/ non-success code.
- System.exit(1);
+ PerfCounter.print();
+ System.exit(exitCode);
}
public static List<FileBackedObject<PermutationResult>> makeResultFiles(
diff --git a/dev/core/src/com/google/gwt/dev/CompilePermsServer.java b/dev/core/src/com/google/gwt/dev/CompilePermsServer.java
index e119a8e..e869898 100644
--- a/dev/core/src/com/google/gwt/dev/CompilePermsServer.java
+++ b/dev/core/src/com/google/gwt/dev/CompilePermsServer.java
@@ -21,6 +21,7 @@
import com.google.gwt.dev.jjs.PermutationResult;
import com.google.gwt.dev.jjs.UnifiedAst;
import com.google.gwt.dev.util.FileBackedObject;
+import com.google.gwt.dev.util.PerfCounter;
import com.google.gwt.dev.util.arg.ArgHandlerLogLevel;
import com.google.gwt.dev.util.arg.OptionLogLevel;
import com.google.gwt.dev.util.log.PrintWriterTreeLogger;
@@ -228,15 +229,18 @@
}
public static void main(String[] args) {
+ int exitCode = -1;
final CompileServerOptions options = new CompileServerOptionsImpl();
if (new ArgProcessor(options).processArgs(args)) {
PrintWriterTreeLogger logger = new PrintWriterTreeLogger();
logger.setMaxDetail(options.getLogLevel());
if (run(options, logger)) {
- System.exit(0);
+ exitCode = 0;
}
}
- System.exit(-1);
+
+ PerfCounter.print();
+ System.exit(exitCode);
}
public static boolean run(CompileServerOptions options, TreeLogger logger) {
diff --git a/dev/core/src/com/google/gwt/dev/jjs/JavaToJavaScriptCompiler.java b/dev/core/src/com/google/gwt/dev/jjs/JavaToJavaScriptCompiler.java
index 91b1579..1025e52 100644
--- a/dev/core/src/com/google/gwt/dev/jjs/JavaToJavaScriptCompiler.java
+++ b/dev/core/src/com/google/gwt/dev/jjs/JavaToJavaScriptCompiler.java
@@ -117,6 +117,7 @@
import com.google.gwt.dev.util.DefaultTextOutput;
import com.google.gwt.dev.util.Empty;
import com.google.gwt.dev.util.Memory;
+import com.google.gwt.dev.util.PerfCounter;
import com.google.gwt.dev.util.PerfLogger;
import com.google.gwt.dev.util.TextOutput;
import com.google.gwt.dev.util.Util;
@@ -623,6 +624,7 @@
*/
jprogram.beginOptimizations();
+ PerfCounter.start("JavaToJavaScriptCompiler.optimize");
PerfLogger.start("optimize");
do {
if (Thread.interrupted()) {
@@ -637,12 +639,14 @@
DataflowOptimizer.exec(jprogram);
}
+ PerfCounter.end("JavaToJavaScriptCompiler.optimize");
PerfLogger.end();
}
protected static boolean optimizeLoop(JProgram jprogram,
boolean isAggressivelyOptimize) {
PerfLogger.start("optimize loop");
+ PerfCounter.start("JavaToJavaScriptCompiler.optimizeLoop");
// Recompute clinits each time, they can become empty.
jprogram.typeOracle.recomputeAfterOptimizations();
@@ -681,6 +685,7 @@
// prove that any types that have been culled from the main tree are
// unreferenced due to type tightening?
+ PerfCounter.end("JavaToJavaScriptCompiler.optimizeLoop");
PerfLogger.end();
return didChange;
}
diff --git a/dev/core/src/com/google/gwt/dev/jjs/impl/DeadCodeElimination.java b/dev/core/src/com/google/gwt/dev/jjs/impl/DeadCodeElimination.java
index b378371..a81bfa8 100644
--- a/dev/core/src/com/google/gwt/dev/jjs/impl/DeadCodeElimination.java
+++ b/dev/core/src/com/google/gwt/dev/jjs/impl/DeadCodeElimination.java
@@ -62,6 +62,7 @@
import com.google.gwt.dev.jjs.ast.JVisitor;
import com.google.gwt.dev.jjs.ast.JWhileStatement;
import com.google.gwt.dev.jjs.ast.js.JMultiExpression;
+import com.google.gwt.dev.util.PerfCounter;
import java.lang.reflect.Method;
import java.util.ArrayList;
@@ -1789,11 +1790,23 @@
}
public static boolean exec(JProgram program) {
- return new DeadCodeElimination(program).execImpl(program);
+ PerfCounter.start("DeadCodeElimination.exec");
+ boolean didChange = new DeadCodeElimination(program).execImpl(program);
+ PerfCounter.end("DeadCodeElimination.exec");
+ if (didChange) {
+ PerfCounter.inc("DeadCodeElimination.exec.didChange");
+ }
+ return didChange;
}
public static boolean exec(JProgram program, JNode node) {
- return new DeadCodeElimination(program).execImpl(node);
+ PerfCounter.start("DeadCodeElimination.execNode");
+ boolean didChange = new DeadCodeElimination(program).execImpl(node);
+ PerfCounter.end("DeadCodeElimination.execNode");
+ if (didChange) {
+ PerfCounter.inc("DeadCodeElimination.execNode.didChange");
+ }
+ return didChange;
}
private final JProgram program;
diff --git a/dev/core/src/com/google/gwt/dev/jjs/impl/Finalizer.java b/dev/core/src/com/google/gwt/dev/jjs/impl/Finalizer.java
index 68b57e8..60b4250 100644
--- a/dev/core/src/com/google/gwt/dev/jjs/impl/Finalizer.java
+++ b/dev/core/src/com/google/gwt/dev/jjs/impl/Finalizer.java
@@ -35,6 +35,7 @@
import com.google.gwt.dev.jjs.ast.JVariableRef;
import com.google.gwt.dev.jjs.ast.JVisitor;
import com.google.gwt.dev.jjs.ast.js.JsniFieldRef;
+import com.google.gwt.dev.util.PerfCounter;
import java.util.HashSet;
import java.util.Set;
@@ -188,7 +189,13 @@
}
public static boolean exec(JProgram program) {
- return new Finalizer().execImpl(program);
+ PerfCounter.start("Finalizer.exec");
+ boolean didChange = new Finalizer().execImpl(program);
+ PerfCounter.end("Finalizer.exec");
+ if (didChange) {
+ PerfCounter.inc("Finalizer.exec.didChange");
+ }
+ return didChange;
}
private final Set<JMethod> isOverriden = new HashSet<JMethod>();
diff --git a/dev/core/src/com/google/gwt/dev/jjs/impl/MakeCallsStatic.java b/dev/core/src/com/google/gwt/dev/jjs/impl/MakeCallsStatic.java
index e9d4e99..652b2a7 100644
--- a/dev/core/src/com/google/gwt/dev/jjs/impl/MakeCallsStatic.java
+++ b/dev/core/src/com/google/gwt/dev/jjs/impl/MakeCallsStatic.java
@@ -43,6 +43,7 @@
import com.google.gwt.dev.js.ast.JsName;
import com.google.gwt.dev.js.ast.JsParameter;
import com.google.gwt.dev.js.ast.JsThisRef;
+import com.google.gwt.dev.util.PerfCounter;
import java.util.ArrayList;
import java.util.HashSet;
@@ -330,7 +331,13 @@
}
public static boolean exec(JProgram program) {
- return new MakeCallsStatic(program).execImpl();
+ PerfCounter.start("MakeCallsStatic.exec");
+ boolean didChange = new MakeCallsStatic(program).execImpl();
+ PerfCounter.end("MakeCallsStatic.exec");
+ if (didChange) {
+ PerfCounter.inc("MakeCallsStatic.exec.didChange");
+ }
+ return didChange;
}
static JExpression makeStaticCall(JMethodCall x, JMethod newMethod) {
diff --git a/dev/core/src/com/google/gwt/dev/jjs/impl/MethodCallTightener.java b/dev/core/src/com/google/gwt/dev/jjs/impl/MethodCallTightener.java
index ae43d85..a7af0c0 100644
--- a/dev/core/src/com/google/gwt/dev/jjs/impl/MethodCallTightener.java
+++ b/dev/core/src/com/google/gwt/dev/jjs/impl/MethodCallTightener.java
@@ -27,6 +27,7 @@
import com.google.gwt.dev.jjs.ast.JNullType;
import com.google.gwt.dev.jjs.ast.JProgram;
import com.google.gwt.dev.jjs.ast.JReferenceType;
+import com.google.gwt.dev.util.PerfCounter;
/**
* Update polymorphic method calls to tighter bindings based on the type of the
@@ -138,7 +139,13 @@
}
public static boolean exec(JProgram program) {
- return new MethodCallTightener(program).execImpl();
+ PerfCounter.start("MethodCallTightener.exec");
+ boolean didChange = new MethodCallTightener(program).execImpl();
+ PerfCounter.end("MethodCallTightener.exec");
+ if (didChange) {
+ PerfCounter.inc("MethodCallTightener.exec.didChange");
+ }
+ return didChange;
}
private final JProgram program;
diff --git a/dev/core/src/com/google/gwt/dev/jjs/impl/MethodInliner.java b/dev/core/src/com/google/gwt/dev/jjs/impl/MethodInliner.java
index 53074a2..b2776c8 100644
--- a/dev/core/src/com/google/gwt/dev/jjs/impl/MethodInliner.java
+++ b/dev/core/src/com/google/gwt/dev/jjs/impl/MethodInliner.java
@@ -36,6 +36,7 @@
import com.google.gwt.dev.jjs.ast.JType;
import com.google.gwt.dev.jjs.ast.JVisitor;
import com.google.gwt.dev.jjs.ast.js.JMultiExpression;
+import com.google.gwt.dev.util.PerfCounter;
import java.util.HashSet;
import java.util.List;
@@ -492,7 +493,13 @@
}
public static boolean exec(JProgram program) {
- return new MethodInliner(program).execImpl();
+ PerfCounter.start("MethodInliner.exec");
+ boolean didChange = new MethodInliner(program).execImpl();
+ PerfCounter.end("MethodInliner.exec");
+ if (didChange) {
+ PerfCounter.inc("MethodInliner.exec.didChange");
+ }
+ return didChange;
}
/**
diff --git a/dev/core/src/com/google/gwt/dev/jjs/impl/Pruner.java b/dev/core/src/com/google/gwt/dev/jjs/impl/Pruner.java
index 4c6850e..8e1b4fb 100644
--- a/dev/core/src/com/google/gwt/dev/jjs/impl/Pruner.java
+++ b/dev/core/src/com/google/gwt/dev/jjs/impl/Pruner.java
@@ -50,6 +50,7 @@
import com.google.gwt.dev.jjs.ast.js.JsniMethodBody;
import com.google.gwt.dev.jjs.ast.js.JsniMethodRef;
import com.google.gwt.dev.js.ast.JsFunction;
+import com.google.gwt.dev.util.PerfCounter;
import java.util.ArrayList;
import java.util.HashMap;
@@ -525,7 +526,13 @@
}
public static boolean exec(JProgram program, boolean noSpecialTypes) {
- return new Pruner(program, noSpecialTypes).execImpl();
+ PerfCounter.start("Pruner.exec");
+ boolean didChange = new Pruner(program, noSpecialTypes).execImpl();
+ PerfCounter.end("Pruner.exec");
+ if (didChange) {
+ PerfCounter.inc("Pruner.exec.didChange");
+ }
+ return didChange;
}
/**
diff --git a/dev/core/src/com/google/gwt/dev/jjs/impl/SameParameterValueOptimizer.java b/dev/core/src/com/google/gwt/dev/jjs/impl/SameParameterValueOptimizer.java
index 4dd95c5..41c20d6 100644
--- a/dev/core/src/com/google/gwt/dev/jjs/impl/SameParameterValueOptimizer.java
+++ b/dev/core/src/com/google/gwt/dev/jjs/impl/SameParameterValueOptimizer.java
@@ -32,6 +32,7 @@
import com.google.gwt.dev.jjs.ast.JVisitor;
import com.google.gwt.dev.jjs.ast.js.JsniMethodBody;
import com.google.gwt.dev.jjs.ast.js.JsniMethodRef;
+import com.google.gwt.dev.util.PerfCounter;
import java.util.HashSet;
import java.util.IdentityHashMap;
@@ -177,7 +178,13 @@
}
public static boolean exec(JProgram program) {
- return new SameParameterValueOptimizer(program).execImpl(program);
+ PerfCounter.start("SameParameterValueOptimizer.exec");
+ boolean didChange = new SameParameterValueOptimizer(program).execImpl(program);
+ PerfCounter.end("SameParameterValueOptimizer.exec");
+ if (didChange) {
+ PerfCounter.inc("SameParameterValueOptimizer.exec.didChange");
+ }
+ return didChange;
}
/**
diff --git a/dev/core/src/com/google/gwt/dev/jjs/impl/TypeTightener.java b/dev/core/src/com/google/gwt/dev/jjs/impl/TypeTightener.java
index 764d198..87de1a3 100644
--- a/dev/core/src/com/google/gwt/dev/jjs/impl/TypeTightener.java
+++ b/dev/core/src/com/google/gwt/dev/jjs/impl/TypeTightener.java
@@ -53,6 +53,7 @@
import com.google.gwt.dev.jjs.ast.JVisitor;
import com.google.gwt.dev.jjs.ast.js.JsniFieldRef;
import com.google.gwt.dev.jjs.ast.js.JsniMethodRef;
+import com.google.gwt.dev.util.PerfCounter;
import java.util.ArrayList;
import java.util.HashSet;
@@ -804,7 +805,13 @@
}
public static boolean exec(JProgram program) {
- return new TypeTightener(program).execImpl();
+ PerfCounter.start("TypeTightener.exec");
+ boolean didChange = new TypeTightener(program).execImpl();
+ PerfCounter.end("TypeTightener.exec");
+ if (didChange) {
+ PerfCounter.inc("TypeTightener.exec.didChange");
+ }
+ return didChange;
}
private static <T, V> void add(T target, V value, Map<T, Set<V>> map) {
diff --git a/dev/core/src/com/google/gwt/dev/jjs/impl/gflow/DataflowOptimizer.java b/dev/core/src/com/google/gwt/dev/jjs/impl/gflow/DataflowOptimizer.java
index 9a70c9b..959905e 100644
--- a/dev/core/src/com/google/gwt/dev/jjs/impl/gflow/DataflowOptimizer.java
+++ b/dev/core/src/com/google/gwt/dev/jjs/impl/gflow/DataflowOptimizer.java
@@ -32,16 +32,19 @@
import com.google.gwt.dev.jjs.impl.gflow.copy.CopyAnalysis;
import com.google.gwt.dev.jjs.impl.gflow.liveness.LivenessAnalysis;
import com.google.gwt.dev.jjs.impl.gflow.unreachable.UnreachableAnalysis;
-import com.google.gwt.dev.util.PerfLogger;
+import com.google.gwt.dev.util.PerfCounter;
import com.google.gwt.dev.util.Preconditions;
/**
*/
public class DataflowOptimizer {
public static boolean exec(JProgram jprogram, JNode node) {
- PerfLogger.start("DataflowOptimizer");
+ PerfCounter.start("DataflowOptimizer.exec");
boolean didChange = new DataflowOptimizer(jprogram).execImpl(node);
- PerfLogger.end();
+ PerfCounter.end("DataflowOptimizer.exec");
+ if (didChange) {
+ PerfCounter.inc("DataflowOptimizer.exec.didChange");
+ }
return didChange;
}
diff --git a/dev/core/src/com/google/gwt/dev/util/PerfCounter.java b/dev/core/src/com/google/gwt/dev/util/PerfCounter.java
new file mode 100644
index 0000000..ccaf50e
--- /dev/null
+++ b/dev/core/src/com/google/gwt/dev/util/PerfCounter.java
@@ -0,0 +1,176 @@
+/*
+ * Copyright 2009 Google Inc.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License"); you may not
+ * use this file except in compliance with the License. You may obtain a copy of
+ * the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+ * WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+ * License for the specific language governing permissions and limitations under
+ * the License.
+ */
+package com.google.gwt.dev.util;
+
+import java.util.ArrayList;
+import java.util.Collections;
+import java.util.HashMap;
+import java.util.List;
+import java.util.Map;
+
+/**
+ * A counter which records bunch of statistics for frequently occuring
+ * operations. Calculates: count, total time, average time, maximum time
+ * & slow operations.
+ */
+public class PerfCounter {
+ private static class OperationStats {
+ private long count = 0;
+ private boolean isCounter = false;
+ private long maxTimeNanos = 0;
+ private long slowCount = 0;
+ private long totalSlowTimeNanos = 0;
+ private long totalTimeNanos = 0;
+
+ @Override
+ public String toString() {
+ StringBuilder result = new StringBuilder();
+
+ if (!isCounter) {
+ result.append(count);
+ result.append("/");
+ result.append(totalTimeNanos / 1000000000.0);
+ result.append("/");
+ result.append(totalTimeNanos / 1000000000.0 / count);
+ result.append("/");
+ result.append(maxTimeNanos / 1000000000.0);
+ result.append("/");
+ result.append(slowCount);
+ result.append("/");
+ result.append(totalSlowTimeNanos * 1.0 / totalTimeNanos);
+ result.append(" ");
+ result.append(
+ "(count/total_time/avg_time/max_time/slow_count/slow_ratio)");
+ } else {
+ result.append(count);
+ result.append(" (count)");
+ }
+
+ return result.toString();
+ }
+ }
+
+ /**
+ * Flag for enabling performance logging.
+ */
+ private static boolean enabled =
+ Boolean.parseBoolean(System.getProperty("gwt.perfcounters"));
+
+ private static final ThreadLocal<Map<String, Long>> operationsStartTime =
+ new ThreadLocal<Map<String,Long>>() {
+ @Override
+ protected Map<String, Long> initialValue() {
+ return new HashMap<String, Long>();
+ }
+ };
+
+ private static final Map<String, OperationStats> operationStats =
+ new HashMap<String, OperationStats>();
+
+ /**
+ * Record the end of the operation.
+ */
+ public static void end(String operation) {
+ if (!enabled) {
+ return;
+ }
+ end(operation, 1 * 1000000000 /* 1 sec */);
+ }
+
+ /**
+ * Record the end of the operation.
+ */
+ public static void end(String operation, long slowThresholdNano) {
+ if (!enabled) {
+ return;
+ }
+ long finishTime = System.nanoTime();
+
+ Map<String, Long> startTimes = operationsStartTime.get();
+
+ Long startTime;
+
+ synchronized (startTimes) {
+ startTime = startTimes.remove(operation);
+ }
+
+ Preconditions.checkNotNull(startTime);
+
+ synchronized (operationStats) {
+ OperationStats stats = getStats(operation);
+
+ stats.count++;
+ long elapsedTime = finishTime - startTime.longValue();
+ stats.totalTimeNanos += elapsedTime;
+ stats.maxTimeNanos = Math.max(stats.maxTimeNanos, elapsedTime);
+ if (elapsedTime > slowThresholdNano) {
+ stats.slowCount++;
+ stats.totalSlowTimeNanos += elapsedTime;
+ }
+ }
+ }
+
+ /**
+ * Increment counter.
+ */
+ public static void inc(String operation) {
+ synchronized (operationStats) {
+ OperationStats stats = getStats(operation);
+ stats.count++;
+ stats.isCounter = true;
+ }
+ }
+
+ public static void print() {
+ if (!enabled) {
+ return;
+ }
+ System.out.println("------------- Perf Counters -------------");
+ synchronized (operationStats) {
+ List<String> keys = new ArrayList<String>(operationStats.keySet());
+ Collections.sort(keys);
+ for (String operation : keys) {
+ System.out.println(operation + ": " + operationStats.get(operation));
+ }
+ }
+ System.out.println("-----------------------------------------");
+ }
+
+ /**
+ * Start operation.
+ */
+ public static void start(String operation) {
+ if (!enabled) {
+ return;
+ }
+ Map<String, Long> startTimes = operationsStartTime.get();
+
+ synchronized (startTimes) {
+ Preconditions.checkState(!startTimes.containsKey(operation));
+ long startTime = System.nanoTime();
+ startTimes.put(operation, new Long(startTime));
+ }
+ }
+
+ private static OperationStats getStats(String operation) {
+ OperationStats stats = operationStats.get(operation);
+ if (stats == null) {
+ stats = new OperationStats();
+ operationStats.put(operation, stats);
+ }
+ return stats;
+ }
+}
