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 }