changeset 24764:722a9603b237

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
author lagergren
date Wed, 21 May 2014 16:12:40 +0200
parents 20971b9687ec
children 1e533bcca9f8
files nashorn/bin/runopt.sh nashorn/src/jdk/nashorn/internal/codegen/CodeGenerator.java nashorn/src/jdk/nashorn/internal/codegen/CompilationPhase.java nashorn/src/jdk/nashorn/internal/codegen/Compiler.java nashorn/src/jdk/nashorn/internal/parser/Parser.java nashorn/src/jdk/nashorn/internal/runtime/ScriptEnvironment.java nashorn/src/jdk/nashorn/internal/runtime/Timing.java nashorn/src/jdk/nashorn/internal/runtime/resources/Options.properties
diffstat 8 files changed, 236 insertions(+), 121 deletions(-) [+]
line wrap: on
line diff
--- 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++;
+    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 @@
      * @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.", \