stan/jdk-24
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

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

Browse Source 
Reviewed-by: sundar, attila
This commit is contained in:
Marcus Lagergren 2014-05-21 16:12:40 +02:00
parent 5ffa8e1bd4
commit 7c50cd3e51
8 changed files with 237 additions and 122 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

7
nashorn/bin/runopt.sh
View File

@ -76,3 +76,10 @@ jdk.nashorn.tools.Shell ${@}
# 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

8
nashorn/src/jdk/nashorn/internal/codegen/CodeGenerator.java
View File

@ -265,7 +265,7 @@ final class CodeGenerator extends NodeOperatorVisitor<CodeGeneratorLexicalContex
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 @@ final class CodeGenerator extends NodeOperatorVisitor<CodeGeneratorLexicalContex
}
@Override
public boolean enterObjectNode(ObjectNode objectNode) {
public boolean enterObjectNode(final ObjectNode objectNode) {
return false;
}
@ -4050,11 +4050,11 @@ final class CodeGenerator extends NodeOperatorVisitor<CodeGeneratorLexicalContex
* @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>");

7
nashorn/src/jdk/nashorn/internal/codegen/CompilationPhase.java
View File

@ -70,7 +70,6 @@ import jdk.nashorn.internal.ir.debug.PrintVisitor;
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 @@ enum CompilationPhase {
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 @@ enum CompilationPhase {
@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 @@ enum CompilationPhase {
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;

69
nashorn/src/jdk/nashorn/internal/codegen/Compiler.java
View File

@ -31,6 +31,7 @@ import static jdk.nashorn.internal.codegen.CompilerConstants.RETURN;
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.RecompilableScriptFunctionData;
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 @@ public final class Compiler implements Loggable {
/** 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 @@ public final class Compiler implements Loggable {
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 @@ public final class Compiler implements Loggable {
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 @@ public final class Compiler implements Loggable {
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 @@ public final class Compiler implements Loggable {
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 @@ public final class Compiler implements Loggable {
return ctxt.getLogger(this.getClass());
}
ScriptEnvironment getScriptEnvironment() {
return env;
}
boolean isOnDemandCompilation() {
return onDemand;
}
@ -474,7 +485,7 @@ public final class Compiler implements Loggable {
*/
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 @@ public final class Compiler implements Loggable {
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));
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 @@ public final class Compiler implements Loggable {
bytecode.remove(name);
}
ScriptEnvironment getEnv() {
return context.getEnv();
}
String getSourceURL() {
return sourceURL;
}

8
nashorn/src/jdk/nashorn/internal/parser/Parser.java
View File

@ -113,7 +113,6 @@ import jdk.nashorn.internal.runtime.RecompilableScriptFunctionData;
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 @@ public class Parser extends AbstractParser implements Loggable {
* @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 @@ public class Parser extends AbstractParser implements Loggable {
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);

23
nashorn/src/jdk/nashorn/internal/runtime/ScriptEnvironment.java
View File

@ -32,6 +32,8 @@ import java.util.Locale;
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 @@ public final class ScriptEnvironment {
/** 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 @@ public final class ScriptEnvironment {
/** Logging */
public final Map<String, LoggerInfo> _loggers;
/** Timing */
public final Timing _timing;
/**
* Constructor
*
@ -302,8 +306,11 @@ public final class ScriptEnvironment {
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 @@ public final class ScriptEnvironment {
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;
}
}

231
nashorn/src/jdk/nashorn/internal/runtime/Timing.java
View File

@ -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++;
private static final String LOGGER_NAME = Timing.class.getAnnotation(Logger.class).name();
for (final Map.Entry<String, Long> entry : TIMINGS.entrySet()) {
final StringBuilder sb = new StringBuilder();
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 @@ public final class Timing {
* @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);
if (accumulatedTime == null) {
accumulatedTime = 0L;
}
TIMINGS.put(module, accumulatedTime + duration);
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);
}
}
}

6
nashorn/src/jdk/nashorn/internal/runtime/resources/Options.properties
View File

@ -284,12 +284,6 @@ nashorn.option.print.symbols = { \
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.", \