001: /*
002: * The contents of this file are subject to the Sapient Public License
003: * Version 1.0 (the "License"); you may not use this file except in compliance
004: * with the License. You may obtain a copy of the License at
005: * http://carbon.sf.net/License.html.
006: *
007: * Software distributed under the License is distributed on an "AS IS" basis,
008: * WITHOUT WARRANTY OF ANY KIND, either express or implied. See the License for
009: * the specific language governing rights and limitations under the License.
010: *
011: * The Original Code is The Carbon Component Framework.
012: *
013: * The Initial Developer of the Original Code is Sapient Corporation
014: *
015: * Copyright (C) 2003 Sapient Corporation. All Rights Reserved.
016: */
017:
018: package org.sape.carbon.services.perflog;
019:
020: import java.util.EmptyStackException;
021: import java.util.Stack;
022:
023: import org.apache.commons.logging.Log;
024: import org.apache.commons.logging.LogFactory;
025:
026: /**
027: * <p>Provides performance logging (sometimes known as profiling) services to
028: * clients. PerfLogger can be used to time operations and log the time of said
029: * operations to the framework logging service.</p>
030: *
031: * <p>The actual timing is accomplished using a stack of objects passed into the
032: * start() method. The stack is kept in thread local storage, which
033: * removes any inter-thread coordination and synchronization issues.</p>
034: *
035: * <p>The times generated by the PerfLogger are elapsed-time, also known as
036: * human time. In a system where only one operation is run at a time, or the
037: * system is not heavily loaded this should closely approximate CPU time. Note
038: * though that times for the same operations can differ significantly based upon
039: * the load of the system.</p>
040: *
041: * <p>In order to maintain the sanity of the stack for performance measurements
042: * it is important that an end() method is actually executed for every start()
043: * method executed. As such, when exceptions are being caught and thrown it is
044: * recommended to structure code as follows:</p>
045: *
046: * <pre>
047: * public void myMethod() {
048: * String tracker = "MyClass.myMethod()"; // key for tracking
049: * PerfLogger.start(tracker);
050: * try {
051: * ....
052: * }
053: * catch (SomeException se) {
054: * ....
055: * }
056: * finally { PerfLogger.end(tracker); }
057: * }</pre>
058: *
059: * <p>Note that any object (not just Strings) can be passed to the start() and
060: * end() methods. This Object should, however, override the .equals() method to
061: * use something other than reference equality if there is a possibility that
062: * the start() and end() methods may receive different, but equal, objects.
063: * Using a custom object (instead of a String) can be useful to format the
064: * message placed into the performance log. The Object is toString()'d as part
065: * of the message logged in the end() method, and hence an object with several
066: * fields, and a custom toString() method can output a well structured message
067: * (perhaps containing classname, methodname and a list of parameters).</p>
068: *
069: * <p>
070: * In order to minimize performance impact of calls to the PerfLogger when
071: * performance logging is not desired, it is possible to indirectly enable and
072: * disable performance logging. Since PerfLogger uses the Carbon loggin
073: * subsystem it is able activate or deactivate based on whether the logging
074: * system is configured to utilize messages at INFO level from this service.
075: * </p>
076: *
077: * Copyright 2000-2003 Sapient
078: * @author Tim Fennell, December 2000
079: * @version $Revision: 1.10 $ ($Author: dvoet $)
080: */
081: public class DefaultPerformanceLogger implements PerformanceLogger {
082:
083: /**
084: * Provides a handle to apache-commons logger
085: */
086: private Log log = LogFactory.getLog(this .getClass());
087:
088: /** Used to indicate an invalid time for a performance measurement. */
089: public static final long INVALID_TIME = -1;
090:
091: /**
092: * <p>Static member variable holding a reference to a ThreadLocal object.
093: * Contains the call stack (implemented as a java.util.Stack). A
094: * ThreadLocal object is a special object, which each Thread gets it's own
095: * copy of. Hence modifying the stack on one thread does not affect any
096: * other threads.</p>
097: */
098: private final ThreadLocal threadLocalCallStack = new ThreadLocal();
099:
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: * <p>Starts a performance measurement. This is accomplished by placing
122: * the object into the stack with a timestamp. The object can then be
123: * retrieved, and the time taken for the operation calculated when
124: * end() is called.</p>
125: *
126: * <p>The object passed in can be any Object, and is not required to be a
127: * String. It is recommended to use Strings or subclasses of Object which
128: * override toString(). This is due to the fact that the object is
129: * written to the performance log using the toString() method.</p>
130: *
131: * @param trackedObject an object representing the operation
132: * being tracked.
133: */
134: public void start(Object trackedObject) {
135: // Only update the performance stack if performance logging is on.
136: if (enabled()) {
137: getCallStack().push(new TrackingInfo(trackedObject));
138: }
139: }
140:
141: /**
142: * <p>Ends a performance measurement. This is accomplished by finding the
143: * most recent item in the stack which matches the object passed in,
144: * according to the .equals() operation. This should usually be the item
145: * at the top of the stack, unless an error has occurred causing one or
146: * more end() calls to be skipped.</p>
147: *
148: * <p>It is recommended that if exceptions could be thrown during a
149: * performance measurement that the end() call be placed in a
150: * finally block to ensure that it is called. This will ensure proper
151: * operation of the PerfLogger.</p>
152: *
153: * <p>If the top most item in the stack does not match the one passed in,
154: * items are popped off the stack until a matching item is found, or the
155: * stack is empty. In the latter case, a time of PerfLogger.INVALID_TIME is
156: * returned, and a warning is entered into the performance log.</p>
157: *
158: * <p>On successful completion of a measurement, a message like the
159: * following is sent to the performance log:<br>
160: *
161: * <code>Performance measurement - tracked object {object.toString()}
162: * completed in #ms</code></p>
163: *
164: * @param trackedObject an object representing the operation
165: * being tracked. This must be equal (according to .equals())
166: * to the object passed in the corresponding call to
167: * start().
168: * @return long the time taken to complete the operation, or
169: * PerfLogger.INVALID_TIME if no matching object was found.
170: */
171: public long end(Object trackedObject) {
172:
173: // Some local variable needed to do the work
174: TrackingInfo currentTrackingInfo = null;
175: Object currentTrackedObject = null;
176: long endTime = DefaultPerformanceLogger.INVALID_TIME;
177: long totalTime = DefaultPerformanceLogger.INVALID_TIME;
178: Stack callStack = null;
179:
180: // Track the end, only if performance logging is enabled.
181: if (enabled()) {
182: callStack = getCallStack();
183:
184: // Take the end time now so that we don't include any of the time
185: // to find the right object and alter the stack.
186: endTime = System.currentTimeMillis();
187:
188: try {
189: // Get the top most item from the call stack
190: currentTrackingInfo = (TrackingInfo) callStack.pop();
191: currentTrackedObject = currentTrackingInfo
192: .getTrackedObject();
193:
194: // Keep going down the call stack until we find the
195: // object that is being tracked. This is needed
196: // because methods may not call end() if the exit via
197: // exception. Recursive methods may not work well
198: // in exception cases...
199: while (!currentTrackedObject.equals(trackedObject)) {
200: currentTrackingInfo = (TrackingInfo) callStack
201: .pop();
202: currentTrackedObject = currentTrackingInfo
203: .getTrackedObject();
204: }
205:
206: totalTime = endTime
207: - currentTrackingInfo.getStartTime();
208:
209: trackTiming(trackedObject, totalTime);
210: } catch (EmptyStackException ese) {
211: // Log a message saying that we couldn't find the object in the
212: // call stack.
213: if (log.isWarnEnabled()) {
214: log
215: .warn("Performance measurement - tracked object "
216: + trackedObject
217: + " could not be located. Call stack now empty.");
218: }
219: totalTime = DefaultPerformanceLogger.INVALID_TIME;
220: }
221: }
222:
223: // Return the time since this track was started.
224: return totalTime;
225: }
226:
227: /**
228: * <p>Clears the call stack, writing to the performance log information
229: * regarding what was in the stack at time of clearance.</p>
230: *
231: * @return <code>int</code> the depth of the stack before clearance.
232: */
233: public int clearStack() {
234: // If performance logging is on, return the true size of the stack,
235: // otherwise return 0.
236: if (enabled()) {
237: int previousDepth = getCallStack().size();
238: logCallStack();
239: getCallStack().clear();
240: if (log.isTraceEnabled()) {
241: log
242: .trace("Performance measurement stack being cleared on thread "
243: + Thread.currentThread().getName());
244: }
245: return previousDepth;
246: } else {
247: return 0;
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
271: .append("Performance measurement stack logged on thread ");
272: message.append(Thread.currentThread().getName());
273: message.append("\n Tracking stack (depth ");
274: message.append(stack.size());
275: message.append("): \n");
276:
277: // Add a little something for each entry in the stack
278: for (int i = 0; i < stack.size(); ++i) {
279: info = (TrackingInfo) stack.get(i);
280:
281: message.append(" ");
282: if (i < 10) {
283: // a half-hearted attempt to align!
284: message.append(" ");
285: }
286: message.append(i);
287: message.append(": ");
288: message.append(info.getTrackedObject());
289: message.append(" [Started at ");
290: message.append(info.getStartTime());
291: message.append("ms]\n");
292: }
293:
294: // Add a footnote with the current time in millis
295: message.append(" Current time is");
296: message.append(System.currentTimeMillis());
297: message.append("ms.");
298:
299: log.info(message.toString());
300: }
301: }
302:
303: /**
304: * Tracks the timing for a given object.
305: *
306: * @param trackedObject the object to track timing on.
307: * @param time the amount of time the object took.
308: */
309: protected void trackTiming(Object trackedObject, long time) {
310:
311: if (log.isInfoEnabled()) {
312: log.info("Performance measurement - item [" + 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: }
|