Timing.java revision 953:221a84ef44c0
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.LinkedHashMap; 32import java.util.List; 33import java.util.Map; 34import java.util.function.Supplier; 35import jdk.nashorn.internal.runtime.logging.DebugLogger; 36import jdk.nashorn.internal.runtime.logging.Loggable; 37import jdk.nashorn.internal.runtime.logging.Logger; 38 39/** 40 * Simple wallclock timing framework 41 */ 42@Logger(name="time") 43public final class Timing implements Loggable { 44 45 private DebugLogger log; 46 private TimeSupplier timeSupplier; 47 private final boolean isEnabled; 48 private final long startTime; 49 50 private static final String LOGGER_NAME = Timing.class.getAnnotation(Logger.class).name(); 51 52 /** 53 * Instantiate singleton timer for ScriptEnvironment 54 * @param isEnabled true if enabled, otherwise we keep the instance around 55 * for code brevity and "isEnabled" checks, but never instantiate anything 56 * inside it 57 */ 58 public Timing(final boolean isEnabled) { 59 this.isEnabled = isEnabled; 60 this.startTime = System.currentTimeMillis(); 61 } 62 63 /** 64 * Get the log info accumulated by this Timing instance 65 * @return log info as one string 66 */ 67 public String getLogInfo() { 68 assert isEnabled(); 69 return timeSupplier.get(); 70 } 71 72 /** 73 * Get the log info accumulated by this Timing instance 74 * @return log info as and array of strings, one per line 75 */ 76 public String[] getLogInfoLines() { 77 assert isEnabled(); 78 return timeSupplier.getStrings(); 79 } 80 81 /** 82 * Check if timing is enabled 83 * @return true if timing is enabled 84 */ 85 boolean isEnabled() { 86 return isEnabled; 87 } 88 89 /** 90 * When timing, this can be called to register a new module for timing 91 * or add to its accumulated time 92 * 93 * @param module module name 94 * @param duration duration to add to accumulated time for module 95 */ 96 public void accumulateTime(final String module, final long duration) { 97 if (isEnabled()) { 98 ensureInitialized(Context.getContextTrusted()); 99 timeSupplier.accumulateTime(module, duration); 100 } 101 } 102 103 private DebugLogger ensureInitialized(final Context context) { 104 //lazy init, as there is not necessarily a context available when 105 //a ScriptEnvironment gets initialize 106 if (isEnabled() && log == null) { 107 log = initLogger(context); 108 if (log.isEnabled()) { 109 this.timeSupplier = new TimeSupplier(); 110 Runtime.getRuntime().addShutdownHook( 111 new Thread() { 112 @Override 113 public void run() { 114 //System.err.println because the context and the output streams may be gone 115 //when the shutdown hook executes 116 final StringBuilder sb = new StringBuilder(); 117 for (final String str : timeSupplier.getStrings()) { 118 sb.append('['). 119 append(Timing.getLoggerName()). 120 append("] "). 121 append(str). 122 append('\n'); 123 } 124 System.err.print(sb); 125 } 126 }); 127 } 128 } 129 return log; 130 } 131 132 static String getLoggerName() { 133 return LOGGER_NAME; 134 } 135 136 @Override 137 public DebugLogger initLogger(final Context context) { 138 return context.getLogger(this.getClass()); 139 } 140 141 @Override 142 public DebugLogger getLogger() { 143 return log; 144 } 145 146 final class TimeSupplier implements Supplier<String> { 147 private final Map<String, Long> timings; 148 149 TimeSupplier() { 150 timings = new LinkedHashMap<>(); 151 } 152 153 String[] getStrings() { 154 final List<String> strs = new ArrayList<>(); 155 final BufferedReader br = new BufferedReader(new StringReader(get())); 156 String line; 157 try { 158 while ((line = br.readLine()) != null) { 159 strs.add(line); 160 } 161 } catch (final IOException e) { 162 throw new RuntimeException(e); 163 } 164 return strs.toArray(new String[strs.size()]); 165 } 166 167 @Override 168 public String get() { 169 final long t = System.currentTimeMillis(); 170 171 long knownTime = 0L; 172 int maxKeyLength = 0; 173 int maxValueLength = 0; 174 175 for (final Map.Entry<String, Long> entry : timings.entrySet()) { 176 maxKeyLength = Math.max(maxKeyLength, entry.getKey().length()); 177 maxValueLength = Math.max(maxValueLength, entry.getValue().toString().length()); 178 } 179 maxKeyLength++; 180 181 final StringBuilder sb = new StringBuilder(); 182 sb.append("Accumulated complation phase Timings:\n\n"); 183 for (final Map.Entry<String, Long> entry : timings.entrySet()) { 184 int len; 185 186 len = sb.length(); 187 sb.append(entry.getKey()); 188 len = sb.length() - len; 189 190 while (len++ < maxKeyLength) { 191 sb.append(' '); 192 } 193 194 final Long duration = entry.getValue(); 195 len = duration.toString().length(); 196 for (int i = 0; i < maxValueLength - len; i++) { 197 sb.append(' '); 198 } 199 200 sb.append(duration). 201 append(" ms\n"); 202 203 knownTime += duration; 204 } 205 206 final long total = t - startTime; 207 sb.append('\n'); 208 sb.append("Total runtime: "). 209 append(total). 210 append(" ms (Non-runtime: "). 211 append(knownTime). 212 append(" ms ["). 213 append((int)(knownTime * 100.0 / total)). 214 append("%])"); 215 216 return sb.toString(); 217 } 218 219 private void accumulateTime(final String module, final long duration) { 220 Long accumulatedTime = timings.get(module); 221 if (accumulatedTime == null) { 222 accumulatedTime = 0L; 223 } 224 timings.put(module, accumulatedTime + duration); 225 } 226 } 227} 228