1 /*
   2  * Copyright (c) 2010, 2016, Oracle and/or its affiliates. All rights reserved.
   3  * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
   4  *
   5  * This code is free software; you can redistribute it and/or modify it
   6  * under the terms of the GNU General Public License version 2 only, as
   7  * published by the Free Software Foundation.  Oracle designates this
   8  * particular file as subject to the "Classpath" exception as provided
   9  * by Oracle in the LICENSE file that accompanied this code.
  10  *
  11  * This code is distributed in the hope that it will be useful, but WITHOUT
  12  * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
  13  * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
  14  * version 2 for more details (a copy is included in the LICENSE file that
  15  * accompanied this code).
  16  *
  17  * You should have received a copy of the GNU General Public License version
  18  * 2 along with this work; if not, write to the Free Software Foundation,
  19  * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
  20  *
  21  * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
  22  * or visit www.oracle.com if you need additional information or have any
  23  * questions.
  24  */
  25 package jdk.nashorn.internal.runtime;
  26 
  27 import java.io.BufferedReader;
  28 import java.io.IOException;
  29 import java.io.StringReader;
  30 import java.util.ArrayList;
  31 import java.util.List;
  32 import java.util.Map;
  33 import java.util.concurrent.ConcurrentHashMap;
  34 import java.util.concurrent.LinkedBlockingQueue;
  35 import java.util.concurrent.TimeUnit;
  36 import java.util.concurrent.atomic.LongAdder;
  37 import java.util.function.Function;
  38 import java.util.function.Supplier;
  39 import jdk.nashorn.internal.codegen.CompileUnit;
  40 import jdk.nashorn.internal.runtime.logging.DebugLogger;
  41 import jdk.nashorn.internal.runtime.logging.Loggable;
  42 import jdk.nashorn.internal.runtime.logging.Logger;
  43 
  44 /**
  45  * Simple wallclock timing framework
  46  */
  47 @Logger(name="time")
  48 public final class Timing implements Loggable {
  49 
  50     private DebugLogger log;
  51     private TimeSupplier timeSupplier;
  52     private final boolean isEnabled;
  53     private final long startTime;
  54 
  55     private static final String LOGGER_NAME = Timing.class.getAnnotation(Logger.class).name();
  56 
  57     /**
  58      * Instantiate singleton timer for ScriptEnvironment
  59      * @param isEnabled true if enabled, otherwise we keep the instance around
  60      *      for code brevity and "isEnabled" checks, but never instantiate anything
  61      *      inside it
  62      */
  63     public Timing(final boolean isEnabled) {
  64         this.isEnabled = isEnabled;
  65         this.startTime = System.nanoTime();
  66     }
  67 
  68     /**
  69      * Get the log info accumulated by this Timing instance
  70      * @return log info as one string
  71      */
  72     public String getLogInfo() {
  73         assert isEnabled();
  74         return timeSupplier.get();
  75     }
  76 
  77     /**
  78      * Get the log info accumulated by this Timing instance
  79      * @return log info as and array of strings, one per line
  80      */
  81     public String[] getLogInfoLines() {
  82         assert isEnabled();
  83         return timeSupplier.getStrings();
  84     }
  85 
  86     /**
  87      * Check if timing is enabled
  88      * @return true if timing is enabled
  89      */
  90     boolean isEnabled() {
  91         return isEnabled;
  92     }
  93 
  94     /**
  95      * When timing, this can be called to register a new module for timing
  96      * or add to its accumulated time
  97      *
  98      * @param module   module name
  99      * @param durationNano duration to add to accumulated time for module, in nanoseconds.
 100      */
 101     public void accumulateTime(final String module, final long durationNano) {
 102         if (isEnabled()) {
 103             ensureInitialized(Context.getContextTrusted());
 104             timeSupplier.accumulateTime(module, durationNano);
 105         }
 106     }
 107 
 108     private DebugLogger ensureInitialized(final Context context) {
 109         //lazy init, as there is not necessarily a context available when
 110         //a ScriptEnvironment gets initialize
 111         if (isEnabled() && log == null) {
 112             log = initLogger(context);
 113             if (log.isEnabled()) {
 114                 this.timeSupplier = new TimeSupplier();
 115                 Runtime.getRuntime().addShutdownHook(
 116                         new Thread() {
 117                             @Override
 118                             public void run() {
 119                                 //System.err.println because the context and the output streams may be gone
 120                                 //when the shutdown hook executes
 121                                 final StringBuilder sb = new StringBuilder();
 122                                 for (final String str : timeSupplier.getStrings()) {
 123                                     sb.append('[').
 124                                         append(Timing.getLoggerName()).
 125                                         append("] ").
 126                                         append(str).
 127                                         append('\n');
 128                                 }
 129                                 System.err.print(sb);
 130                             }
 131                         });
 132             }
 133         }
 134         return log;
 135     }
 136 
 137     static String getLoggerName() {
 138         return LOGGER_NAME;
 139     }
 140 
 141     @Override
 142     public DebugLogger initLogger(final Context context) {
 143         return context.getLogger(this.getClass());
 144     }
 145 
 146     @Override
 147     public DebugLogger getLogger() {
 148         return log;
 149     }
 150 
 151     /**
 152      * Takes a duration in nanoseconds, and returns a string representation of it rounded to milliseconds.
 153      * @param durationNano duration in nanoseconds
 154      * @return the string representing the duration in milliseconds.
 155      */
 156     public static String toMillisPrint(final long durationNano) {
 157         return Long.toString(TimeUnit.NANOSECONDS.toMillis(durationNano));
 158     }
 159 
 160     final class TimeSupplier implements Supplier<String> {
 161         private final Map<String, LongAdder> timings = new ConcurrentHashMap<>();
 162         private final LinkedBlockingQueue<String> orderedTimingNames = new LinkedBlockingQueue<>();
 163         private final Function<String, LongAdder> newTimingCreator = s -> {
 164             orderedTimingNames.add(s);
 165             return new LongAdder();
 166         };
 167 
 168         String[] getStrings() {
 169             final List<String> strs = new ArrayList<>();
 170             final BufferedReader br = new BufferedReader(new StringReader(get()));
 171             String line;
 172             try {
 173                 while ((line = br.readLine()) != null) {
 174                     strs.add(line);
 175                 }
 176             } catch (final IOException e) {
 177                 throw new RuntimeException(e);
 178             }
 179             return strs.toArray(new String[0]);
 180         }
 181 
 182         @Override
 183         public String get() {
 184             final long t = System.nanoTime();
 185 
 186             long knownTime = 0L;
 187             int  maxKeyLength = 0;
 188             int  maxValueLength = 0;
 189 
 190             for (final Map.Entry<String, LongAdder> entry : timings.entrySet()) {
 191                 maxKeyLength   = Math.max(maxKeyLength, entry.getKey().length());
 192                 maxValueLength = Math.max(maxValueLength, toMillisPrint(entry.getValue().longValue()).length());
 193             }
 194             maxKeyLength++;
 195 
 196             final StringBuilder sb = new StringBuilder();
 197             sb.append("Accumulated compilation phase timings:\n\n");
 198             for (final String timingName: orderedTimingNames) {
 199                 int len;
 200 
 201                 len = sb.length();
 202                 sb.append(timingName);
 203                 len = sb.length() - len;
 204 
 205                 while (len++ < maxKeyLength) {
 206                     sb.append(' ');
 207                 }
 208 
 209                 final long duration = timings.get(timingName).longValue();
 210                 final String strDuration = toMillisPrint(duration);
 211                 len = strDuration.length();
 212                 for (int i = 0; i < maxValueLength - len; i++) {
 213                     sb.append(' ');
 214                 }
 215 
 216                 sb.append(strDuration).
 217                     append(" ms\n");
 218 
 219                 knownTime += duration;
 220             }
 221 
 222             final long total = t - startTime;
 223             return sb.append("\nTotal runtime: ").
 224                 append(toMillisPrint(total)).
 225                 append(" ms (Non-runtime: ").
 226                 append(toMillisPrint(knownTime)).
 227                 append(" ms [").
 228                 append((int)(knownTime * 100.0 / total)).
 229                 append("%])").
 230                 append("\n\nEmitted compile units: ").
 231                 append(CompileUnit.getEmittedUnitCount()).
 232                 append("\nCompile units installed as named classes: ").
 233                 append(Context.getNamedInstalledScriptCount()).
 234                 append("\nCompile units installed as anonymous classes: ").
 235                 append(Context.getAnonymousInstalledScriptCount()).
 236                 toString();
 237         }
 238 
 239         private void accumulateTime(final String module, final long duration) {
 240             timings.computeIfAbsent(module, newTimingCreator).add(duration);
 241         }
 242     }
 243 }