DefaultPerformanceLogger


1   /*
2    * The contents of this file are subject to the Sapient Public License
3    * Version 1.0 (the "License"); you may not use this file except in compliance
4    * with the License. You may obtain a copy of the License at
5    * http://carbon.sf.net/License.html.
6    *
7    * Software distributed under the License is distributed on an "AS IS" basis,
8    * WITHOUT WARRANTY OF ANY KIND, either express or implied. See the License for
9    * the specific language governing rights and limitations under the License.
10   *
11   * The Original Code is The Carbon Component Framework.
12   *
13   * The Initial Developer of the Original Code is Sapient Corporation
14   *
15   * Copyright (C) 2003 Sapient Corporation. All Rights Reserved.
16   */
17  
18  package org.sape.carbon.services.perflog;
19  
20  import java.util.EmptyStackException  ;
21  import java.util.Stack  ;
22  
23  import org.apache.commons.logging.Log;
24  import org.apache.commons.logging.LogFactory;
25  
26  /**
27   * <p>Provides performance logging (sometimes known as profiling) services to
28   * clients. PerfLogger can be used to time operations and log the time of said
29   * operations to the framework logging service.</p>
30   *
31   * <p>The actual timing is accomplished using a stack of objects passed into the
32   * start() method. The stack is kept in thread local storage, which
33   * removes any inter-thread coordination and synchronization issues.</p>
34   *
35   * <p>The times generated by the PerfLogger are elapsed-time, also known as
36   * human time. In a system where only one operation is run at a time, or the
37   * system is not heavily loaded this should closely approximate CPU time. Note
38   * though that times for the same operations can differ significantly based upon
39   * the load of the system.</p>
40   *
41   * <p>In order to maintain the sanity of the stack for performance measurements
42   * it is important that an end() method is actually executed for every start()
43   * method executed. As such, when exceptions are being caught and thrown it is
44   * recommended to structure code as follows:</p>
45   *
46   * <pre>
47   * public void myMethod() {
48   *     String tracker = "MyClass.myMethod()"; // key for tracking
49   *     PerfLogger.start(tracker);
50   *     try {
51   *        ....
52   *     }
53   *     catch (SomeException se) {
54   *        ....
55   *     }
56   *     finally { PerfLogger.end(tracker); }
57   * }</pre>
58   *
59   * <p>Note that any object (not just Strings) can be passed to the start() and
60   * end() methods. This Object should, however, override the .equals() method to
61   * use something other than reference equality if there is a possibility that
62   * the start() and end() methods may receive different, but equal, objects.
63   * Using a custom object (instead of a String) can be useful to format the
64   * message placed into the performance log.  The Object is toString()'d as part
65   * of the message logged in the end() method, and hence an object with several
66   * fields, and a custom toString() method can output a well structured message
67   * (perhaps containing classname, methodname and a list of parameters).</p>
68   *
69   * <p>
70   * In order to minimize performance impact of calls to the PerfLogger when
71   * performance logging is not desired, it is possible to indirectly enable and
72   * disable performance logging. Since PerfLogger uses the Carbon loggin
73   * subsystem it is able activate or deactivate based on whether the logging
74   * system is configured to utilize messages at INFO level from this service.
75   * </p>
76   *
77   * Copyright 2000-2003 Sapient
78   * @author Tim Fennell, December 2000
79   * @version $Revision: 1.10 $ ($Author: dvoet $)
80   */
81  public class DefaultPerformanceLogger implements PerformanceLogger {
82  
83      /**
84       * Provides a handle to apache-commons logger
85       */
86      private Log log = LogFactory.getLog(this.getClass());
87  
88      /** Used to indicate an invalid time for a performance measurement. */
89      public static final long INVALID_TIME = -1;
90  
91      /**
92       * <p>Static member variable holding a reference to a ThreadLocal object.
93       * Contains the call stack (implemented as a java.util.Stack). A
94       * ThreadLocal object is a special object, which each Thread gets it's own
95       * copy of. Hence modifying the stack on one thread does not affect any
96       * other threads.</p>
97       */
98      private final ThreadLocal   threadLocalCallStack = new ThreadLocal  ();
99  
100     /**
101      * <p>Utility method that returns a stack object kept in thread local
102      * storage. Used to lazily instantiate the stack and place it into the
103      * ThreadLocal storage.</p>
104      *
105      * @return stack object kept in thread local
106      */
107     protected Stack   getCallStack() {
108         Stack   stack = (Stack  ) threadLocalCallStack.get();
109 
110         // if the stack isn't initialized yet, then create one and dump it in
111         if (stack == null) {
112             stack = new Stack  ();
113             threadLocalCallStack.set(stack);
114         }
115 
116         // return the stack
117         return stack;
118     }
119 
120 
121     /**
122      * <p>Starts a performance measurement.  This is accomplished by placing
123      * the object into the stack with a timestamp. The object can then be
124      * retrieved, and the time taken for the operation calculated when
125      * end() is called.</p>
126      *
127      * <p>The object passed in can be any Object, and is not required to be a
128      * String. It is recommended to use Strings or subclasses of Object which
129      * override toString(). This is due to the fact that the object is
130      * written to the performance log using the toString() method.</p>
131      *
132      * @param trackedObject an object representing the operation
133      *              being tracked.
134      */
135     public void start(Object   trackedObject) {
136         // Only update the performance stack if performance logging is on.
137         if (enabled()) {
138             getCallStack().push(new TrackingInfo(trackedObject));
139         }
140     }
141 
142 
143     /**
144      * <p>Ends a performance measurement.  This is accomplished by finding the
145      * most recent item in the stack which matches the object passed in,
146      * according to the .equals() operation.  This should usually be the item
147      * at the top of the stack, unless an error has occurred causing one or
148      * more end() calls to be skipped.</p>
149      *
150      * <p>It is recommended that if exceptions could be thrown during a
151      * performance measurement that the end() call be placed in a
152      * finally block to ensure that it is called. This will ensure proper
153      * operation of the PerfLogger.</p>
154      *
155      * <p>If the top most item in the stack does not match the one passed in,
156      * items are popped off the stack until a matching item is found, or the
157      * stack is empty. In the latter case, a time of PerfLogger.INVALID_TIME is
158      * returned, and a warning is entered into the performance log.</p>
159      *
160      * <p>On successful completion of a measurement, a message like the
161      * following is sent to the performance log:<br>
162      *
163      * <code>Performance measurement - tracked object {object.toString()}
164      *       completed in #ms</code></p>
165      *
166      * @param trackedObject an object representing the operation
167      *              being tracked. This must be equal (according to .equals())
168      *              to the object passed in the corresponding call to
169      *              start().
170      * @return long the time taken to complete the operation, or
171      *               PerfLogger.INVALID_TIME if no matching object was found.
172      */
173     public long end(Object   trackedObject) {
174 
175         // Some local variable needed to do the work
176         TrackingInfo currentTrackingInfo = null;
177         Object   currentTrackedObject = null;
178         long endTime  = DefaultPerformanceLogger.INVALID_TIME;
179         long totalTime = DefaultPerformanceLogger.INVALID_TIME;
180         Stack   callStack = null;
181 
182         // Track the end, only if performance logging is enabled.
183         if (enabled()) {
184             callStack = getCallStack();
185 
186             // Take the end time now so that we don't include any of the time
187             // to find the right object and alter the stack.
188             endTime = System.currentTimeMillis();
189 
190             try {
191                 // Get the top most item from the call stack
192                 currentTrackingInfo = (TrackingInfo) callStack.pop();
193                 currentTrackedObject = currentTrackingInfo.getTrackedObject();
194 
195                 // Keep going down the call stack until we find the
196                 // object that is being tracked.  This is needed
197                 // because methods may not call end() if the exit via
198                 // exception.  Recursive methods may not work well
199                 // in exception cases...
200                 while (!currentTrackedObject.equals(trackedObject)) {
201                     currentTrackingInfo = (TrackingInfo) callStack.pop();
202                     currentTrackedObject =
203                         currentTrackingInfo.getTrackedObject();
204                 }
205 
206                 totalTime = endTime - currentTrackingInfo.getStartTime();
207 
208                 trackTiming(trackedObject, totalTime);
209             } catch (EmptyStackException   ese) {
210                 // Log a message saying that we couldn't find the object in the
211                 // call stack.
212                 if (log.isWarnEnabled()) {
213                     log.warn("Performance measurement - tracked object "
214                         + trackedObject
215                         + " could not be located.  Call stack now empty.");
216                 }
217                 totalTime = DefaultPerformanceLogger.INVALID_TIME;
218             }
219         }
220 
221         // Return the time since this track was started.
222         return totalTime;
223     }
224 
225 
226     /**
227      * <p>Clears the call stack, writing to the performance log information
228      * regarding what was in the stack at time of clearance.</p>
229      *
230      * @return <code>int</code> the depth of the stack before clearance.
231      */
232     public int clearStack() {
233         // If performance logging is on, return the true size of the stack,
234         // otherwise return 0.
235         if (enabled()) {
236             int previousDepth = getCallStack().size();
237             logCallStack();
238             getCallStack().clear();
239             if (log.isTraceEnabled()) {
240                 log.trace(
241                     "Performance measurement stack being cleared on thread "
242                     + Thread.currentThread().getName());
243             }
244             return previousDepth;
245         } else {
246             return 0;
247         }
248     }
249 
250 
251     /**
252      * <p>Logs information regarding the current state of the performance stack
253      * to the performance log. Information logged is of the format:</p>
254      *
255      * <pre>Performance measurement stack logged on thread <threadName>
256      *        Tracking stack (depth n):
257      *          0. item0.toString() [Started at ######ms]
258      *          1. item1.toString() [Started at ######ms]
259      *        Current time is ######ms</pre>
260      */
261     public void logCallStack() {
262         // Log the callstack only if performance logging is enabled.
263         if (enabled()) {
264             Stack   stack = getCallStack();
265             StringBuffer   message = new StringBuffer  (256);
266             TrackingInfo info = null;
267 
268             // Put some header info together, including the thread name and
269             // stack depth
270             message.append("Performance measurement stack logged on thread ");
271             message.append(Thread.currentThread().getName());
272             message.append("\n  Tracking stack (depth ");
273             message.append(stack.size());
274             message.append("): \n");
275 
276             // Add a little something for each entry in the stack
277             for (int i = 0; i < stack.size(); ++i) {
278                 info = (TrackingInfo) stack.get(i);
279 
280                 message.append("     ");
281                 if (i < 10) {
282                     // a half-hearted attempt to align!
283                      message.append(" ");
284                 }
285                 message.append(i);
286                 message.append(": ");
287                 message.append(info.getTrackedObject());
288                 message.append(" [Started at ");
289                 message.append(info.getStartTime());
290                 message.append("ms]\n");
291             }
292 
293             // Add a footnote with the current time in millis
294             message.append("  Current time is");
295             message.append(System.currentTimeMillis());
296             message.append("ms.");
297 
298             log.info(message.toString());
299         }
300     }
301 
302     /**
303      * Tracks the timing for a given object.
304      *
305      * @param trackedObject the object to track timing on.
306      * @param time the amount of time the object took.
307      */
308     protected void trackTiming(Object   trackedObject, long time) {
309 
310         if (log.isInfoEnabled()) {
311             log.info("Performance measurement - item ["
312                 + trackedObject
313                 + "] executed in [" + time + "ms].");
314         }
315     }
316 
317     /**
318      * <p>Determines if performance logging is enabled.</p>
319      * @return <code>boolean</code> true if performance logging is enabled,
320      *               otherwise false.
321      */
322     public boolean enabled() {
323         return log.isInfoEnabled();
324     }
325 
326 
327 }
A to Z: JavaDoc & Examples Daily Java News & Articles Open Source Projects Open Source Codes Free Computer Books Remove Frame
Popular Tags