Timing.java revision 1010:fc80190e129f
1177633Sdfr/* 2177633Sdfr * Copyright (c) 2010, 2014, Oracle and/or its affiliates. All rights reserved. 3261046Smav * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. 4261046Smav * 5261046Smav * This code is free software; you can redistribute it and/or modify it 6177633Sdfr * under the terms of the GNU General Public License version 2 only, as 7261046Smav * published by the Free Software Foundation. Oracle designates this 8261046Smav * particular file as subject to the "Classpath" exception as provided 9261046Smav * by Oracle in the LICENSE file that accompanied this code. 10261046Smav * 11261046Smav * This code is distributed in the hope that it will be useful, but WITHOUT 12261046Smav * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or 13261046Smav * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License 14261046Smav * version 2 for more details (a copy is included in the LICENSE file that 15261046Smav * accompanied this code). 16261046Smav * 17261046Smav * You should have received a copy of the GNU General Public License version 18261046Smav * 2 along with this work; if not, write to the Free Software Foundation, 19261046Smav * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA. 20261046Smav * 21261046Smav * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA 22261046Smav * or visit www.oracle.com if you need additional information or have any 23261046Smav * questions. 24261046Smav */ 25261046Smavpackage jdk.nashorn.internal.runtime; 26261046Smav 27261046Smavimport java.io.BufferedReader; 28261046Smavimport java.io.IOException; 29177633Sdfrimport java.io.StringReader; 30177633Sdfrimport java.util.ArrayList; 31177633Sdfrimport java.util.LinkedHashMap; 32177633Sdfrimport java.util.List; 33177633Sdfrimport java.util.Map; 34177633Sdfrimport java.util.concurrent.TimeUnit; 35177633Sdfrimport java.util.function.Supplier; 36177633Sdfrimport jdk.nashorn.internal.runtime.logging.DebugLogger; 37177633Sdfrimport jdk.nashorn.internal.runtime.logging.Loggable; 38177633Sdfrimport jdk.nashorn.internal.runtime.logging.Logger; 39177633Sdfr 40177633Sdfr/** 41177633Sdfr * Simple wallclock timing framework 42177633Sdfr */ 43177633Sdfr@Logger(name="time") 44177633Sdfrpublic final class Timing implements Loggable { 45177633Sdfr 46177633Sdfr private DebugLogger log; 47177633Sdfr private TimeSupplier timeSupplier; 48177633Sdfr private final boolean isEnabled; 49177633Sdfr private final long startTime; 50177633Sdfr 51184588Sdfr private static final String LOGGER_NAME = Timing.class.getAnnotation(Logger.class).name(); 52177633Sdfr 53184588Sdfr /** 54177633Sdfr * Instantiate singleton timer for ScriptEnvironment 55184588Sdfr * @param isEnabled true if enabled, otherwise we keep the instance around 56177633Sdfr * for code brevity and "isEnabled" checks, but never instantiate anything 57184588Sdfr * inside it 58177633Sdfr */ 59267742Smav public Timing(final boolean isEnabled) { 60261055Smav this.isEnabled = isEnabled; 61177633Sdfr this.startTime = System.nanoTime(); 62177633Sdfr } 63177633Sdfr 64177633Sdfr /** 65184588Sdfr * Get the log info accumulated by this Timing instance 66177633Sdfr * @return log info as one string 67177685Sdfr */ 68177633Sdfr public String getLogInfo() { 69177633Sdfr assert isEnabled(); 70184588Sdfr return timeSupplier.get(); 71177633Sdfr } 72177633Sdfr 73177633Sdfr /** 74267742Smav * Get the log info accumulated by this Timing instance 75184588Sdfr * @return log info as and array of strings, one per line 76290203Swollman */ 77261054Smav public String[] getLogInfoLines() { 78314034Savg assert isEnabled(); 79177633Sdfr return timeSupplier.getStrings(); 80177633Sdfr } 81177633Sdfr 82184588Sdfr /** 83184588Sdfr * Check if timing is enabled 84267742Smav * @return true if timing is enabled 85184588Sdfr */ 86177633Sdfr boolean isEnabled() { 87184588Sdfr return isEnabled; 88177633Sdfr } 89177633Sdfr 90267742Smav /** 91267742Smav * When timing, this can be called to register a new module for timing 92177633Sdfr * or add to its accumulated time 93177633Sdfr * 94177633Sdfr * @param module module name 95177633Sdfr * @param durationNano duration to add to accumulated time for module, in nanoseconds. 96184588Sdfr */ 97184588Sdfr public void accumulateTime(final String module, final long durationNano) { 98184588Sdfr if (isEnabled()) { 99177633Sdfr ensureInitialized(Context.getContextTrusted()); 100261055Smav timeSupplier.accumulateTime(module, durationNano); 101184588Sdfr } 102184588Sdfr } 103267742Smav 104267742Smav private DebugLogger ensureInitialized(final Context context) { 105267742Smav //lazy init, as there is not necessarily a context available when 106267742Smav //a ScriptEnvironment gets initialize 107267742Smav if (isEnabled() && log == null) { 108267742Smav log = initLogger(context); 109267742Smav if (log.isEnabled()) { 110267742Smav this.timeSupplier = new TimeSupplier(); 111267742Smav Runtime.getRuntime().addShutdownHook( 112267742Smav new Thread() { 113267742Smav @Override 114267742Smav public void run() { 115177633Sdfr //System.err.println because the context and the output streams may be gone 116184588Sdfr //when the shutdown hook executes 117290203Swollman final StringBuilder sb = new StringBuilder(); 118290203Swollman for (final String str : timeSupplier.getStrings()) { 119290203Swollman sb.append('['). 120290203Swollman append(Timing.getLoggerName()). 121290203Swollman append("] "). 122184588Sdfr append(str). 123290203Swollman append('\n'); 124290203Swollman } 125184588Sdfr System.err.print(sb); 126184588Sdfr } 127184588Sdfr }); 128184588Sdfr } 129184588Sdfr } 130267742Smav return log; 131267742Smav } 132184588Sdfr 133184588Sdfr static String getLoggerName() { 134267742Smav return LOGGER_NAME; 135267742Smav } 136267742Smav 137267742Smav @Override 138267742Smav public DebugLogger initLogger(final Context context) { 139267742Smav return context.getLogger(this.getClass()); 140184588Sdfr } 141267742Smav 142267742Smav @Override 143184588Sdfr public DebugLogger getLogger() { 144290203Swollman return log; 145184588Sdfr } 146290203Swollman 147184588Sdfr /** 148184588Sdfr * Takes a duration in nanoseconds, and returns a string representation of it rounded to milliseconds. 149290203Swollman * @param durationNano duration in nanoseconds 150184588Sdfr * @return the string representing the duration in milliseconds. 151290203Swollman */ 152184588Sdfr public static String toMillisPrint(final long durationNano) { 153184588Sdfr return Long.toString(TimeUnit.NANOSECONDS.toMillis(durationNano)); 154290203Swollman } 155184588Sdfr 156290203Swollman final class TimeSupplier implements Supplier<String> { 157184588Sdfr private final Map<String, Long> timings; 158184588Sdfr 159290203Swollman TimeSupplier() { 160184588Sdfr timings = new LinkedHashMap<>(); 161290203Swollman } 162184588Sdfr 163184588Sdfr String[] getStrings() { 164217326Smdf final List<String> strs = new ArrayList<>(); 165184588Sdfr final BufferedReader br = new BufferedReader(new StringReader(get())); 166184588Sdfr String line; 167184588Sdfr try { 168184588Sdfr while ((line = br.readLine()) != null) { 169217326Smdf strs.add(line); 170184588Sdfr } 171184588Sdfr } catch (final IOException e) { 172184588Sdfr throw new RuntimeException(e); 173184588Sdfr } 174184588Sdfr return strs.toArray(new String[strs.size()]); 175177633Sdfr } 176177633Sdfr 177177633Sdfr @Override 178314034Savg public String get() { 179314034Savg final long t = System.nanoTime(); 180314034Savg 181314034Savg long knownTime = 0L; 182314034Savg int maxKeyLength = 0; 183314034Savg int maxValueLength = 0; 184177633Sdfr 185267742Smav for (final Map.Entry<String, Long> entry : timings.entrySet()) { 186184588Sdfr maxKeyLength = Math.max(maxKeyLength, entry.getKey().length()); 187177633Sdfr maxValueLength = Math.max(maxValueLength, toMillisPrint(entry.getValue()).length()); 188261055Smav } 189184588Sdfr maxKeyLength++; 190267742Smav 191177633Sdfr final StringBuilder sb = new StringBuilder(); 192184588Sdfr sb.append("Accumulated compilation phase timings:\n\n"); 193177633Sdfr for (final Map.Entry<String, Long> entry : timings.entrySet()) { 194267742Smav int len; 195267742Smav 196267742Smav len = sb.length(); 197267742Smav sb.append(entry.getKey()); 198267742Smav len = sb.length() - len; 199267742Smav 200267742Smav while (len++ < maxKeyLength) { 201267742Smav sb.append(' '); 202177633Sdfr } 203267742Smav 204267742Smav final Long duration = entry.getValue(); 205267742Smav final String strDuration = toMillisPrint(duration); 206177633Sdfr len = strDuration.length(); 207267742Smav for (int i = 0; i < maxValueLength - len; i++) { 208261055Smav sb.append(' '); 209177633Sdfr } 210177633Sdfr 211177633Sdfr sb.append(strDuration). 212177633Sdfr append(" ms\n"); 213261055Smav 214261055Smav knownTime += duration; 215261055Smav } 216261055Smav 217261055Smav final long total = t - startTime; 218193603Srmacklem sb.append('\n'); 219314034Savg sb.append("Total runtime: "). 220177633Sdfr append(toMillisPrint(total)). 221314034Savg append(" ms (Non-runtime: "). 222314034Savg append(toMillisPrint(knownTime)). 223314034Savg append(" ms ["). 224314034Savg append((int)(knownTime * 100.0 / total)). 225314034Savg append("%])"); 226314034Savg 227314034Savg return sb.toString(); 228314034Savg } 229267742Smav 230267742Smav private void accumulateTime(final String module, final long duration) { 231267742Smav Long accumulatedTime = timings.get(module); 232184588Sdfr if (accumulatedTime == null) { 233193436Srmacklem accumulatedTime = 0L; 234193436Srmacklem } 235184588Sdfr timings.put(module, accumulatedTime + duration); 236184588Sdfr } 237184588Sdfr } 238184588Sdfr} 239177633Sdfr