View Javadoc
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 }