1 /* 2 * Copyright (c) 2002, 2013, 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 26 27 28 package sun.misc; 29 30 import java.util.Vector; 31 import java.io.FileWriter; 32 import java.io.File; 33 import java.io.OutputStreamWriter; 34 import java.io.Writer; 35 36 /** 37 * This class is intended to be a central place for the jdk to 38 * log timing events of interest. There is pre-defined event 39 * of startTime, as well as a general 40 * mechanism of setting arbitrary times in an array. 41 * All unreserved times in the array can be used by callers 42 * in application-defined situations. The caller is responsible 43 * for setting and getting all times and for doing whatever 44 * analysis is interesting; this class is merely a central container 45 * for those timing values. 46 * Note that, due to the variables in this class being static, 47 * use of particular time values by multiple applets will cause 48 * confusing results. For example, if plugin runs two applets 49 * simultaneously, the initTime for those applets will collide 50 * and the results may be undefined. 51 * <P> 52 * To automatically track startup performance in an app or applet, 53 * use the command-line parameter sun.perflog as follows:<BR> 54 * -Dsun.perflog[=file:<filename>] 55 * <BR> 56 * where simply using the parameter with no value will enable output 57 * to the console and a value of "file:<filename>" will cause 58 * that given filename to be created and used for all output. 59 * <P> 60 * By default, times are measured using System.currentTimeMillis(). To use 61 * System.nanoTime() instead, add the command-line parameter:<BR> 62 -Dsun.perflog.nano=true 63 * <BR> 64 * <P> 65 * <B>Warning: Use at your own risk!</B> 66 * This class is intended for internal testing 67 * purposes only and may be removed at any time. More 68 * permanent monitoring and profiling APIs are expected to be 69 * developed for future releases and this class will cease to 70 * exist once those APIs are in place. 71 * @author Chet Haase 72 */ 73 public class PerformanceLogger { 74 75 // Timing values of global interest 76 private static final int START_INDEX = 0; // VM start 77 private static final int LAST_RESERVED = START_INDEX; 78 79 private static boolean perfLoggingOn = false; 80 private static boolean useNanoTime = false; 81 private static Vector<TimeData> times; 82 private static String logFileName = null; 83 private static Writer logWriter = null; 84 private static long baseTime; 85 86 static { 87 String perfLoggingProp = 88 java.security.AccessController.doPrivileged( 89 new sun.security.action.GetPropertyAction("sun.perflog")); 90 if (perfLoggingProp != null) { 91 perfLoggingOn = true; 92 93 // Check if we should use nanoTime 94 String perfNanoProp = 95 java.security.AccessController.doPrivileged( 96 new sun.security.action.GetPropertyAction("sun.perflog.nano")); 97 if (perfNanoProp != null) { 98 useNanoTime = true; 99 } 100 101 // Now, figure out what the user wants to do with the data 102 if (perfLoggingProp.regionMatches(true, 0, "file:", 0, 5)) { 103 logFileName = perfLoggingProp.substring(5); 104 } 105 if (logFileName != null) { 106 if (logWriter == null) { 107 java.security.AccessController.doPrivileged( 108 new java.security.PrivilegedAction<Void>() { 109 public Void run() { 110 try { 111 File logFile = new File(logFileName); 112 logFile.createNewFile(); 113 logWriter = new FileWriter(logFile); 114 } catch (Exception e) { 115 System.out.println(e + ": Creating logfile " + 116 logFileName + 117 ". Log to console"); 118 } 119 return null; 120 } 121 }); 122 } 123 } 124 if (logWriter == null) { 125 logWriter = new OutputStreamWriter(System.out); 126 } 127 } 128 times = new Vector<TimeData>(10); 129 // Reserve predefined slots 130 for (int i = 0; i <= LAST_RESERVED; ++i) { 131 times.add(new TimeData("Time " + i + " not set", 0)); 132 } 133 } 134 135 /** 136 * Returns status of whether logging is enabled or not. This is 137 * provided as a convenience method so that users do not have to 138 * perform the same GetPropertyAction check as above to determine whether 139 * to enable performance logging. 140 */ 141 public static boolean loggingEnabled() { 142 return perfLoggingOn; 143 } 144 145 146 /** 147 * Internal class used to store time/message data together. 148 */ 149 static class TimeData { 150 String message; 151 long time; 152 153 TimeData(String message, long time) { 154 this.message = message; 155 this.time = time; 156 } 157 158 String getMessage() { 159 return message; 160 } 161 162 long getTime() { 163 return time; 164 } 165 } 166 167 /** 168 * Return the current time, in millis or nanos as appropriate 169 */ 170 private static long getCurrentTime() { 171 if (useNanoTime) { 172 return System.nanoTime(); 173 } else { 174 return System.currentTimeMillis(); 175 } 176 } 177 178 /** 179 * Sets the start time. Ideally, this is the earliest time available 180 * during the startup of a Java applet or application. This time is 181 * later used to analyze the difference between the initial startup 182 * time and other events in the system (such as an applet's init time). 183 */ 184 public static void setStartTime(String message) { 185 if (loggingEnabled()) { 186 long nowTime = getCurrentTime(); 187 setStartTime(message, nowTime); 188 } 189 } 190 191 /** 192 * Sets the base time, output can then 193 * be displayed as offsets from the base time;. 194 */ 195 public static void setBaseTime(long time) { 196 if (loggingEnabled()) { 197 baseTime = time; 198 } 199 } 200 201 /** 202 * Sets the start time. 203 * This version of the method is 204 * given the time to log, instead of expecting this method to 205 * get the time itself. This is done in case the time was 206 * recorded much earlier than this method was called. 207 */ 208 public static void setStartTime(String message, long time) { 209 if (loggingEnabled()) { 210 times.set(START_INDEX, new TimeData(message, time)); 211 } 212 } 213 214 /** 215 * Gets the start time, which should be the time when 216 * the java process started, prior to the VM actually being 217 * loaded. 218 */ 219 public static long getStartTime() { 220 if (loggingEnabled()) { 221 return times.get(START_INDEX).getTime(); 222 } else { 223 return 0; 224 } 225 } 226 227 /** 228 * Sets the value of a given time and returns the index of the 229 * slot that that time was stored in. 230 */ 231 public static int setTime(String message) { 232 if (loggingEnabled()) { 233 long nowTime = getCurrentTime(); 234 return setTime(message, nowTime); 235 } else { 236 return 0; 237 } 238 } 239 240 /** 241 * Sets the value of a given time and returns the index of the 242 * slot that that time was stored in. 243 * This version of the method is 244 * given the time to log, instead of expecting this method to 245 * get the time itself. This is done in case the time was 246 * recorded much earlier than this method was called. 247 */ 248 public static int setTime(String message, long time) { 249 if (loggingEnabled()) { 250 // times is already synchronized, but we need to ensure that 251 // the size used in times.set() is the same used when returning 252 // the index of that operation. 253 synchronized (times) { 254 times.add(new TimeData(message, time)); 255 return (times.size() - 1); 256 } 257 } else { 258 return 0; 259 } 260 } 261 262 /** 263 * Returns time at given index. 264 */ 265 public static long getTimeAtIndex(int index) { 266 if (loggingEnabled()) { 267 return times.get(index).getTime(); 268 } else { 269 return 0; 270 } 271 } 272 273 /** 274 * Returns message at given index. 275 */ 276 public static String getMessageAtIndex(int index) { 277 if (loggingEnabled()) { 278 return times.get(index).getMessage(); 279 } else { 280 return null; 281 } 282 } 283 284 /** 285 * Outputs all data to parameter-specified Writer object 286 */ 287 public static void outputLog(Writer writer) { 288 if (loggingEnabled()) { 289 try { 290 synchronized(times) { 291 for (int i = 0; i < times.size(); ++i) { 292 TimeData td = times.get(i); 293 if (td != null) { 294 writer.write(i + " " + td.getMessage() + ": " + 295 (td.getTime() - baseTime) + "\n"); 296 297 } 298 } 299 } 300 writer.flush(); 301 } catch (Exception e) { 302 System.out.println(e + ": Writing performance log to " + 303 writer); 304 } 305 } 306 } 307 308 /** 309 * Outputs all data to whatever location the user specified 310 * via sun.perflog command-line parameter. 311 */ 312 public static void outputLog() { 313 outputLog(logWriter); 314 } 315 }