Mercurial > people > rkennke > jdk9-shenandoah-final > nashorn
changeset 988:d81f7c897bdf
8055923: collect timings using System.nanoTime
Reviewed-by: hannesw, lagergren
author | attila |
---|---|
date | Tue, 26 Aug 2014 11:45:36 +0200 |
parents | f03ee361fa76 |
children | 3c354c3af1d8 |
files | src/jdk.scripting.nashorn/share/classes/jdk/nashorn/internal/codegen/CompilationPhase.java src/jdk.scripting.nashorn/share/classes/jdk/nashorn/internal/parser/Parser.java src/jdk.scripting.nashorn/share/classes/jdk/nashorn/internal/runtime/Timing.java |
diffstat | 3 files changed, 27 insertions(+), 15 deletions(-) [+] |
line wrap: on
line diff
--- a/src/jdk.scripting.nashorn/share/classes/jdk/nashorn/internal/codegen/CompilationPhase.java Tue Aug 26 11:42:07 2014 +0200 +++ b/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/src/jdk.scripting.nashorn/share/classes/jdk/nashorn/internal/parser/Parser.java Tue Aug 26 11:42:07 2014 +0200 +++ b/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/src/jdk.scripting.nashorn/share/classes/jdk/nashorn/internal/runtime/Timing.java Tue Aug 26 11:42:07 2014 +0200 +++ b/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("%])");