Timing.java revision 1430:79781ce06df7
1/* 2 * Copyright (c) 2010, 2014, 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 */ 25package jdk.nashorn.internal.runtime; 26 27import java.io.BufferedReader; 28import java.io.IOException; 29import java.io.StringReader; 30import java.util.ArrayList; 31import java.util.List; 32import java.util.Map; 33import java.util.concurrent.ConcurrentHashMap; 34import java.util.concurrent.LinkedBlockingQueue; 35import java.util.concurrent.TimeUnit; 36import java.util.concurrent.atomic.LongAdder; 37import java.util.function.Function; 38import java.util.function.Supplier; 39import jdk.nashorn.internal.codegen.CompileUnit; 40import jdk.nashorn.internal.runtime.logging.DebugLogger; 41import jdk.nashorn.internal.runtime.logging.Loggable; 42import jdk.nashorn.internal.runtime.logging.Logger; 43 44/** 45 * Simple wallclock timing framework 46 */ 47@Logger(name="time") 48public 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[strs.size()]); 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} 244