8043633: In order to remove global state outside of contexts, make sure Timing class is an instance and not a static global collection of data. Move into Context. Move -Dnashorn.timing to an official logging option.
Reviewed-by: sundar, attila
--- a/nashorn/bin/runopt.sh Wed May 21 15:38:11 2014 +0200
+++ b/nashorn/bin/runopt.sh Wed May 21 16:12:40 2014 +0200
@@ -76,3 +76,10 @@
# compiler threads is set to 1 for determinsm.
#-XX:+PrintOptoAssembly -XX:-TieredCompilation -XX:CICompilerCount=1 \
+
+#[20/05/14 14:05:54] Albert Noll: IncreaseFirstTierCompileThresholdAt=XX
+#[20/05/14 14:06:03] Albert Noll: where X is between 1..100
+#[20/05/14 14:06:33] Albert Noll: The smaller X is, the less methods are being compiled with C1
+#[20/05/14 14:07:37] Albert Noll: You can also do more aggressive sweeping with:
+# NmethodSweepActivity=XX
+#[20/05/14 14:07:47] Albert Noll: The default value is 10
--- a/nashorn/src/jdk/nashorn/internal/codegen/CodeGenerator.java Wed May 21 15:38:11 2014 +0200
+++ b/nashorn/src/jdk/nashorn/internal/codegen/CodeGenerator.java Wed May 21 16:12:40 2014 +0200
@@ -265,7 +265,7 @@
super(new CodeGeneratorLexicalContext());
this.compiler = compiler;
this.continuationEntryPoints = continuationEntryPoints;
- this.callSiteFlags = compiler.getEnv()._callsite_flags;
+ this.callSiteFlags = compiler.getScriptEnvironment()._callsite_flags;
this.log = initLogger(compiler.getContext());
}
@@ -2256,7 +2256,7 @@
}
@Override
- public boolean enterObjectNode(ObjectNode objectNode) {
+ public boolean enterObjectNode(final ObjectNode objectNode) {
return false;
}
@@ -4050,11 +4050,11 @@
* @param ident identifier for block or function where applicable
*/
private void printSymbols(final Block block, final String ident) {
- if (!compiler.getEnv()._print_symbols) {
+ if (!compiler.getScriptEnvironment()._print_symbols) {
return;
}
- final PrintWriter out = compiler.getEnv().getErr();
+ final PrintWriter out = compiler.getScriptEnvironment().getErr();
out.println("[BLOCK in '" + ident + "']");
if (!block.printSymbols(out)) {
out.println("<no symbols>");
--- a/nashorn/src/jdk/nashorn/internal/codegen/CompilationPhase.java Wed May 21 15:38:11 2014 +0200
+++ b/nashorn/src/jdk/nashorn/internal/codegen/CompilationPhase.java Wed May 21 16:12:40 2014 +0200
@@ -70,7 +70,6 @@
import jdk.nashorn.internal.ir.visitor.NodeVisitor;
import jdk.nashorn.internal.runtime.RecompilableScriptFunctionData;
import jdk.nashorn.internal.runtime.ScriptEnvironment;
-import jdk.nashorn.internal.runtime.Timing;
import jdk.nashorn.internal.runtime.logging.DebugLogger;
/**
@@ -272,7 +271,7 @@
FunctionNode transform(final Compiler compiler, final CompilationPhases phases, final FunctionNode fn) {
final FunctionNode newFunctionNode = (FunctionNode)fn.accept(new LocalVariableTypesCalculator(compiler));
- final ScriptEnvironment senv = compiler.getEnv();
+ final ScriptEnvironment senv = compiler.getScriptEnvironment();
final PrintWriter err = senv.getErr();
//TODO separate phase for the debug printouts for abstraction and clarity
@@ -421,7 +420,7 @@
@Override
FunctionNode transform(final Compiler compiler, final CompilationPhases phases, final FunctionNode fn) {
- final ScriptEnvironment senv = compiler.getEnv();
+ final ScriptEnvironment senv = compiler.getScriptEnvironment();
FunctionNode newFunctionNode = fn;
@@ -659,7 +658,7 @@
protected FunctionNode end(final Compiler compiler, final FunctionNode functionNode) {
compiler.getLogger().unindent();
endTime = System.currentTimeMillis();
- Timing.accumulateTime(toString(), endTime - startTime);
+ compiler.getScriptEnvironment()._timing.accumulateTime(toString(), endTime - startTime);
isFinished = true;
return functionNode;
--- a/nashorn/src/jdk/nashorn/internal/codegen/Compiler.java Wed May 21 15:38:11 2014 +0200
+++ b/nashorn/src/jdk/nashorn/internal/codegen/Compiler.java Wed May 21 16:12:40 2014 +0200
@@ -31,6 +31,7 @@
import static jdk.nashorn.internal.codegen.CompilerConstants.SCOPE;
import static jdk.nashorn.internal.codegen.CompilerConstants.THIS;
import static jdk.nashorn.internal.codegen.CompilerConstants.VARARGS;
+import static jdk.nashorn.internal.runtime.logging.DebugLogger.quote;
import java.io.File;
import java.lang.invoke.MethodType;
@@ -61,7 +62,6 @@
import jdk.nashorn.internal.runtime.ScriptEnvironment;
import jdk.nashorn.internal.runtime.ScriptObject;
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;
@@ -81,6 +81,8 @@
/** Name of the objects package */
public static final String OBJECTS_PACKAGE = "jdk/nashorn/internal/objects";
+ private final ScriptEnvironment env;
+
private final Source source;
private final String sourceName;
@@ -263,6 +265,10 @@
return this == COMPILE_ALL_RESTOF || this == COMPILE_FROM_BYTECODE_RESTOF;
}
+ String getDesc() {
+ return desc;
+ }
+
String toString(final String prefix) {
final StringBuilder sb = new StringBuilder();
for (final CompilationPhase phase : phases) {
@@ -345,6 +351,7 @@
final int[] continuationEntryPoints,
final ScriptObject runtimeScope) {
this.context = context;
+ this.env = env;
this.installer = installer;
this.constantData = new ConstantData();
this.compileUnits = CompileUnit.createCompileUnitSet();
@@ -359,7 +366,7 @@
this.invalidatedProgramPoints = invalidatedProgramPoints == null ? new HashMap<Integer, Type>() : invalidatedProgramPoints;
this.continuationEntryPoints = continuationEntryPoints == null ? null: continuationEntryPoints.clone();
this.typeEvaluator = new TypeEvaluator(this, runtimeScope);
- this.firstCompileUnitName = firstCompileUnitName(context.getEnv());
+ this.firstCompileUnitName = firstCompileUnitName();
this.strict = isStrict;
if (!initialized) {
@@ -389,7 +396,7 @@
return mangled != null ? mangled : baseName;
}
- private String firstCompileUnitName(final ScriptEnvironment env) {
+ private String firstCompileUnitName() {
final StringBuilder sb = new StringBuilder(SCRIPTS_PACKAGE).
append('/').
append(CompilerConstants.DEFAULT_SCRIPT_NAME.symbolName()).
@@ -427,6 +434,10 @@
return ctxt.getLogger(this.getClass());
}
+ ScriptEnvironment getScriptEnvironment() {
+ return env;
+ }
+
boolean isOnDemandCompilation() {
return onDemand;
}
@@ -474,7 +485,7 @@
*/
public FunctionNode compile(final FunctionNode functionNode, final CompilationPhases phases) throws CompilationException {
- log.info("Starting compile job for ", DebugLogger.quote(functionNode.getName()), " phases=", phases);
+ log.info("Starting compile job for ", DebugLogger.quote(functionNode.getName()), " phases=", quote(phases.getDesc()));
log.indent();
final String name = DebugLogger.quote(functionNode.getName());
@@ -485,59 +496,33 @@
newFunctionNode.uniqueName(reservedName);
}
- final boolean fine = log.levelFinerThanOrEqual(Level.FINE);
final boolean info = log.levelFinerThanOrEqual(Level.INFO);
+ final DebugLogger timeLogger = env.isTimingEnabled() ? env._timing.getLogger() : null;
+
long time = 0L;
for (final CompilationPhase phase : phases) {
- if (fine) {
- log.fine("Phase ", phase.toString(), " starting for ", name);
- }
+ log.fine(phase, " starting for ", quote(name));
+ newFunctionNode = phase.apply(this, phases, newFunctionNode);
+ log.fine(phase, " done for function ", quote(name));
- newFunctionNode = phase.apply(this, phases, newFunctionNode);
-
- if (getEnv()._print_mem_usage) {
+ if (env._print_mem_usage) {
printMemoryUsage(functionNode, phase.toString());
}
- final long duration = Timing.isEnabled() ? phase.getEndTime() - phase.getStartTime() : 0L;
- time += duration;
-
- if (fine) {
- final StringBuilder sb = new StringBuilder();
-
- sb.append("Phase ").
- append(phase.toString()).
- append(" done for function ").
- append(name);
-
- if (duration > 0L) {
- sb.append(" in ").
- append(duration).
- append(" ms ");
- }
-
- log.fine(sb);
- }
+ time += (env.isTimingEnabled() ? phase.getEndTime() - phase.getStartTime() : 0L);
}
log.unindent();
if (info) {
final StringBuilder sb = new StringBuilder();
- sb.append("Compile job for ").
- append(newFunctionNode.getSource()).
- append(':').
- append(DebugLogger.quote(newFunctionNode.getName())).
- append(" finished");
-
- if (time > 0L) {
- sb.append(" in ").
- append(time).
- append(" ms");
+ sb.append("Compile job for ").append(newFunctionNode.getSource()).append(':').append(quote(newFunctionNode.getName())).append(" finished");
+ if (time > 0L && timeLogger != null) {
+ assert env.isTimingEnabled();
+ sb.append(" in ").append(time).append(" ms");
}
-
log.info(sb);
}
@@ -582,10 +567,6 @@
bytecode.remove(name);
}
- ScriptEnvironment getEnv() {
- return context.getEnv();
- }
-
String getSourceURL() {
return sourceURL;
}
--- a/nashorn/src/jdk/nashorn/internal/parser/Parser.java Wed May 21 15:38:11 2014 +0200
+++ b/nashorn/src/jdk/nashorn/internal/parser/Parser.java Wed May 21 16:12:40 2014 +0200
@@ -113,7 +113,6 @@
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;
@@ -254,7 +253,8 @@
* @return function node resulting from successful parse
*/
public FunctionNode parse(final String scriptName, final int startPos, final int len, final boolean allowPropertyFunction) {
- final long t0 = Timing.isEnabled() ? System.currentTimeMillis() : 0L;
+ final boolean isTimingEnabled = env.isTimingEnabled();
+ final long t0 = isTimingEnabled ? System.currentTimeMillis() : 0L;
log.info(this, " begin for '", scriptName, "'");
try {
@@ -274,8 +274,8 @@
return null;
} finally {
final String end = this + " end '" + scriptName + "'";
- if (Timing.isEnabled()) {
- Timing.accumulateTime(toString(), System.currentTimeMillis() - t0);
+ if (isTimingEnabled) {
+ env._timing.accumulateTime(toString(), System.currentTimeMillis() - t0);
log.info(end, "' in ", System.currentTimeMillis() - t0, " ms");
} else {
log.info(end);
--- a/nashorn/src/jdk/nashorn/internal/runtime/ScriptEnvironment.java Wed May 21 15:38:11 2014 +0200
+++ b/nashorn/src/jdk/nashorn/internal/runtime/ScriptEnvironment.java Wed May 21 16:12:40 2014 +0200
@@ -32,6 +32,8 @@
import java.util.Map;
import java.util.StringTokenizer;
import java.util.TimeZone;
+import java.util.logging.Level;
+
import jdk.nashorn.internal.codegen.Namespace;
import jdk.nashorn.internal.runtime.linker.NashornCallSiteDescriptor;
import jdk.nashorn.internal.runtime.options.KeyValueOption;
@@ -93,8 +95,7 @@
/** Argument passed to compile only if optimistic compilation should take place */
public static final String COMPILE_ONLY_OPTIMISTIC_ARG = "optimistic";
- /**
- * Behavior when encountering a function declaration in a lexical context where only statements are acceptable
+ /** * Behavior when encountering a function declaration in a lexical context where only statements are acceptable
* (function declarations are source elements, but not statements).
*/
public enum FunctionStatementBehavior {
@@ -199,6 +200,9 @@
/** Logging */
public final Map<String, LoggerInfo> _loggers;
+ /** Timing */
+ public final Timing _timing;
+
/**
* Constructor
*
@@ -302,8 +306,11 @@
this._locale = Locale.getDefault();
}
- final LoggingOption lo = (LoggingOption)options.get("log");
- this._loggers = lo == null ? new HashMap<String, LoggerInfo>() : lo.getLoggers();
+ final LoggingOption loggingOption = (LoggingOption)options.get("log");
+ this._loggers = loggingOption == null ? new HashMap<String, LoggerInfo>() : loggingOption.getLoggers();
+
+ final LoggerInfo timeLoggerInfo = _loggers.get(Timing.getLoggerName());
+ this._timing = new Timing(timeLoggerInfo != null && timeLoggerInfo.getLevel() != Level.OFF);
}
/**
@@ -360,4 +367,12 @@
return _loggers.get(name) != null;
}
+ /**
+ * Check if compilation/runtime timings are enabled
+ * @return true if enabled
+ */
+ public boolean isTimingEnabled() {
+ return _timing != null ? _timing.isEnabled() : false;
+ }
+
}
--- a/nashorn/src/jdk/nashorn/internal/runtime/Timing.java Wed May 21 15:38:11 2014 +0200
+++ b/nashorn/src/jdk/nashorn/internal/runtime/Timing.java Wed May 21 16:12:40 2014 +0200
@@ -1,5 +1,5 @@
/*
- * Copyright (c) 2010, 2013, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2010, 2014, Oracle and/or its affiliates. All rights reserved.
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
*
* This code is free software; you can redistribute it and/or modify it
@@ -24,69 +24,67 @@
*/
package jdk.nashorn.internal.runtime;
+import java.io.BufferedReader;
+import java.io.IOException;
+import java.io.StringReader;
+import java.util.ArrayList;
import java.util.LinkedHashMap;
+import java.util.List;
import java.util.Map;
+import java.util.function.Supplier;
-import jdk.nashorn.internal.runtime.options.Options;
+import jdk.nashorn.internal.runtime.logging.DebugLogger;
+import jdk.nashorn.internal.runtime.logging.Loggable;
+import jdk.nashorn.internal.runtime.logging.Logger;
/**
* Simple wallclock timing framework
*/
-public final class Timing {
- private static final boolean ENABLED = Options.getBooleanProperty("nashorn.time");
- private static final Map<String, Long> TIMINGS;
- private static final long START_TIME;
+@Logger(name="time")
+public final class Timing implements Loggable {
- static {
- if (ENABLED) {
- TIMINGS = new LinkedHashMap<>();
- START_TIME = System.currentTimeMillis();
- Runtime.getRuntime().addShutdownHook(new Thread() {
- @Override
- public void run() {
- final long t = System.currentTimeMillis();
- long knownTime = 0L;
- int maxLength = 0;
+ private DebugLogger log;
+ private TimeSupplier timeSupplier;
+ private final boolean isEnabled;
+ private final long startTime;
- for (final Map.Entry<String, Long> entry : TIMINGS.entrySet()) {
- maxLength = Math.max(maxLength, entry.getKey().length());
- }
- maxLength++;
-
- for (final Map.Entry<String, Long> entry : TIMINGS.entrySet()) {
- final StringBuilder sb = new StringBuilder();
+ private static final String LOGGER_NAME = Timing.class.getAnnotation(Logger.class).name();
- sb.append(entry.getKey());
- while (sb.length() < maxLength) {
- sb.append(' ');
- }
-
- final long duration = entry.getValue();
- sb.append(duration);
- sb.append(' ');
- sb.append(" ms");
-
- knownTime += duration;
-
- System.err.println(sb.toString()); //Context err is gone by shutdown TODO
- }
-
- final long total = t - START_TIME;
- System.err.println("Total runtime: " + total + " ms (Non-runtime: " + knownTime + " ms [" + (int)(knownTime * 100.0 / total) + "%])");
- }
- });
- } else {
- TIMINGS = null;
- START_TIME = 0L;
- }
+ /**
+ * Instantiate singleton timer for ScriptEnvironment
+ * @param isEnabled true if enabled, otherwise we keep the instance around
+ * for code brevity and "isEnabled" checks, but never instantiate anything
+ * inside it
+ */
+ public Timing(final boolean isEnabled) {
+ this.isEnabled = isEnabled;
+ this.startTime = System.currentTimeMillis();
}
/**
- * Check if timing is inabled
+ * Get the log info accumulated by this Timing instance
+ * @return log info as one string
+ */
+ public String getLogInfo() {
+ assert isEnabled();
+ return timeSupplier.get();
+ }
+
+ /**
+ * Get the log info accumulated by this Timing instance
+ * @return log info as and array of strings, one per line
+ */
+ public String[] getLogInfoLines() {
+ assert isEnabled();
+ return timeSupplier.getStrings();
+ }
+
+ /**
+ * Check if timing is enabled
* @return true if timing is enabled
*/
- public static boolean isEnabled() {
- return ENABLED;
+ boolean isEnabled() {
+ return isEnabled;
}
/**
@@ -96,14 +94,135 @@
* @param module module name
* @param duration duration to add to accumulated time for module
*/
- public static void accumulateTime(final String module, final long duration) {
- if (Timing.isEnabled()) {
- Long accumulatedTime = TIMINGS.get(module);
+ public void accumulateTime(final String module, final long duration) {
+ if (isEnabled()) {
+ ensureInitialized(Context.getContextTrusted());
+ timeSupplier.accumulateTime(module, duration);
+ }
+ }
+
+ private DebugLogger ensureInitialized(final Context context) {
+ //lazy init, as there is not necessarily a context available when
+ //a ScriptEnvironment gets initialize
+ if (isEnabled() && log == null) {
+ log = initLogger(context);
+ if (log.isEnabled()) {
+ this.timeSupplier = new TimeSupplier();
+ Runtime.getRuntime().addShutdownHook(
+ new Thread() {
+ @Override
+ public void run() {
+ //System.err.println because the context and the output streams may be gone
+ //when the shutdown hook executes
+ final StringBuilder sb = new StringBuilder();
+ for (final String str : timeSupplier.getStrings()) {
+ sb.append('[').
+ append(Timing.getLoggerName()).
+ append("] ").
+ append(str).
+ append('\n');
+ }
+ System.err.print(sb);
+ }
+ });
+ }
+ }
+ return log;
+ }
+
+ static String getLoggerName() {
+ return LOGGER_NAME;
+ }
+
+ @Override
+ public DebugLogger initLogger(final Context context) {
+ return context.getLogger(this.getClass());
+ }
+
+ @Override
+ public DebugLogger getLogger() {
+ return log;
+ }
+
+ final class TimeSupplier implements Supplier<String> {
+ private final Map<String, Long> timings;
+
+ TimeSupplier() {
+ timings = new LinkedHashMap<>();
+ }
+
+ String[] getStrings() {
+ final List<String> strs = new ArrayList<>();
+ final BufferedReader br = new BufferedReader(new StringReader(get()));
+ String line;
+ try {
+ while ((line = br.readLine()) != null) {
+ strs.add(line);
+ }
+ } catch (final IOException e) {
+ throw new RuntimeException(e);
+ }
+ return strs.toArray(new String[strs.size()]);
+ }
+
+ @Override
+ public String get() {
+ final long t = System.currentTimeMillis();
+
+ long knownTime = 0L;
+ int maxKeyLength = 0;
+ int maxValueLength = 0;
+
+ for (final Map.Entry<String, Long> entry : timings.entrySet()) {
+ maxKeyLength = Math.max(maxKeyLength, entry.getKey().length());
+ maxValueLength = Math.max(maxValueLength, entry.getValue().toString().length());
+ }
+ maxKeyLength++;
+
+ final StringBuilder sb = new StringBuilder();
+ sb.append("Accumulated complation phase Timings:\n\n");
+ for (final Map.Entry<String, Long> entry : timings.entrySet()) {
+ int len;
+
+ len = sb.length();
+ sb.append(entry.getKey());
+ len = sb.length() - len;
+
+ while (len++ < maxKeyLength) {
+ sb.append(' ');
+ }
+
+ final Long duration = entry.getValue();
+ len = duration.toString().length();
+ for (int i = 0; i < maxValueLength - len; i++) {
+ sb.append(' ');
+ }
+
+ sb.append(duration).
+ append(" ms\n");
+
+ knownTime += duration;
+ }
+
+ final long total = t - startTime;
+ sb.append('\n');
+ sb.append("Total runtime: ").
+ append(total).
+ append(" ms (Non-runtime: ").
+ append(knownTime).
+ append(" ms [").
+ append((int)(knownTime * 100.0 / total)).
+ append("%])");
+
+ return sb.toString();
+ }
+
+ private void accumulateTime(final String module, final long duration) {
+ Long accumulatedTime = timings.get(module);
if (accumulatedTime == null) {
accumulatedTime = 0L;
}
- TIMINGS.put(module, accumulatedTime + duration);
+ timings.put(module, accumulatedTime + duration);
}
}
-
}
--- a/nashorn/src/jdk/nashorn/internal/runtime/resources/Options.properties Wed May 21 15:38:11 2014 +0200
+++ b/nashorn/src/jdk/nashorn/internal/runtime/resources/Options.properties Wed May 21 16:12:40 2014 +0200
@@ -284,12 +284,6 @@
desc="Print the symbol table." \
}
-nashorn.option.range.analysis = { \
- name="--range-analysis", \
- is_undocumented=true, \
- desc="EXPERIMENTAL: Do range analysis using known compile time types, and try to narrow number types" \
-}
-
nashorn.option.D = { \
name="-D", \
desc="-Dname=value. Set a system property. This option can be repeated.", \