--- a/nashorn/src/jdk.scripting.nashorn/share/classes/jdk/nashorn/internal/codegen/CompilationPhase.java Tue Aug 26 11:42:07 2014 +0200
+++ b/nashorn/src/jdk.scripting.nashorn/share/classes/jdk/nashorn/internal/codegen/CompilationPhase.java Tue Aug 26 11:45:36 2014 +0200
@@ -631,7 +631,7 @@
throw new CompilationException(sb.toString());
}
- startTime = System.currentTimeMillis();
+ startTime = System.nanoTime();
return functionNode;
}
@@ -644,7 +644,7 @@
*/
protected FunctionNode end(final Compiler compiler, final FunctionNode functionNode) {
compiler.getLogger().unindent();
- endTime = System.currentTimeMillis();
+ endTime = System.nanoTime();
compiler.getScriptEnvironment()._timing.accumulateTime(toString(), endTime - startTime);
isFinished = true;
--- a/nashorn/src/jdk.scripting.nashorn/share/classes/jdk/nashorn/internal/parser/Parser.java Tue Aug 26 11:42:07 2014 +0200
+++ b/nashorn/src/jdk.scripting.nashorn/share/classes/jdk/nashorn/internal/parser/Parser.java Tue Aug 26 11:45:36 2014 +0200
@@ -116,6 +116,7 @@
import jdk.nashorn.internal.runtime.ScriptEnvironment;
import jdk.nashorn.internal.runtime.ScriptingFunctions;
import jdk.nashorn.internal.runtime.Source;
+import jdk.nashorn.internal.runtime.Timing;
import jdk.nashorn.internal.runtime.logging.DebugLogger;
import jdk.nashorn.internal.runtime.logging.Loggable;
import jdk.nashorn.internal.runtime.logging.Logger;
@@ -257,7 +258,7 @@
*/
public FunctionNode parse(final String scriptName, final int startPos, final int len, final boolean allowPropertyFunction) {
final boolean isTimingEnabled = env.isTimingEnabled();
- final long t0 = isTimingEnabled ? System.currentTimeMillis() : 0L;
+ final long t0 = isTimingEnabled ? System.nanoTime() : 0L;
log.info(this, " begin for '", scriptName, "'");
try {
@@ -278,8 +279,8 @@
} finally {
final String end = this + " end '" + scriptName + "'";
if (isTimingEnabled) {
- env._timing.accumulateTime(toString(), System.currentTimeMillis() - t0);
- log.info(end, "' in ", System.currentTimeMillis() - t0, " ms");
+ env._timing.accumulateTime(toString(), System.nanoTime() - t0);
+ log.info(end, "' in ", Timing.toMillisPrint(System.nanoTime() - t0), " ms");
} else {
log.info(end);
}
--- a/nashorn/src/jdk.scripting.nashorn/share/classes/jdk/nashorn/internal/runtime/Timing.java Tue Aug 26 11:42:07 2014 +0200
+++ b/nashorn/src/jdk.scripting.nashorn/share/classes/jdk/nashorn/internal/runtime/Timing.java Tue Aug 26 11:45:36 2014 +0200
@@ -31,6 +31,7 @@
import java.util.LinkedHashMap;
import java.util.List;
import java.util.Map;
+import java.util.concurrent.TimeUnit;
import java.util.function.Supplier;
import jdk.nashorn.internal.runtime.logging.DebugLogger;
import jdk.nashorn.internal.runtime.logging.Loggable;
@@ -57,7 +58,7 @@
*/
public Timing(final boolean isEnabled) {
this.isEnabled = isEnabled;
- this.startTime = System.currentTimeMillis();
+ this.startTime = System.nanoTime();
}
/**
@@ -91,12 +92,12 @@
* or add to its accumulated time
*
* @param module module name
- * @param duration duration to add to accumulated time for module
+ * @param durationNano duration to add to accumulated time for module, in nanoseconds.
*/
- public void accumulateTime(final String module, final long duration) {
+ public void accumulateTime(final String module, final long durationNano) {
if (isEnabled()) {
ensureInitialized(Context.getContextTrusted());
- timeSupplier.accumulateTime(module, duration);
+ timeSupplier.accumulateTime(module, durationNano);
}
}
@@ -143,6 +144,15 @@
return log;
}
+ /**
+ * Takes a duration in nanoseconds, and returns a string representation of it rounded to milliseconds.
+ * @param durationNano duration in nanoseconds
+ * @return the string representing the duration in milliseconds.
+ */
+ public static String toMillisPrint(final long durationNano) {
+ return Long.toString(TimeUnit.NANOSECONDS.toMillis(durationNano));
+ }
+
final class TimeSupplier implements Supplier<String> {
private final Map<String, Long> timings;
@@ -166,7 +176,7 @@
@Override
public String get() {
- final long t = System.currentTimeMillis();
+ final long t = System.nanoTime();
long knownTime = 0L;
int maxKeyLength = 0;
@@ -174,7 +184,7 @@
for (final Map.Entry<String, Long> entry : timings.entrySet()) {
maxKeyLength = Math.max(maxKeyLength, entry.getKey().length());
- maxValueLength = Math.max(maxValueLength, entry.getValue().toString().length());
+ maxValueLength = Math.max(maxValueLength, toMillisPrint(entry.getValue()).length());
}
maxKeyLength++;
@@ -192,12 +202,13 @@
}
final Long duration = entry.getValue();
- len = duration.toString().length();
+ final String strDuration = toMillisPrint(duration);
+ len = strDuration.length();
for (int i = 0; i < maxValueLength - len; i++) {
sb.append(' ');
}
- sb.append(duration).
+ sb.append(strDuration).
append(" ms\n");
knownTime += duration;
@@ -206,9 +217,9 @@
final long total = t - startTime;
sb.append('\n');
sb.append("Total runtime: ").
- append(total).
+ append(toMillisPrint(total)).
append(" ms (Non-runtime: ").
- append(knownTime).
+ append(toMillisPrint(knownTime)).
append(" ms [").
append((int)(knownTime * 100.0 / total)).
append("%])");