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