/*
* The contents of this file are subject to the Sapient Public License
* Version 1.0 (the "License"); you may not use this file except in compliance
* with the License. You may obtain a copy of the License at
* http://carbon.sf.net/License.html.
*
* Software distributed under the License is distributed on an "AS IS" basis,
* WITHOUT WARRANTY OF ANY KIND, either express or implied. See the License for
* the specific language governing rights and limitations under the License.
*
* The Original Code is The Carbon Component Framework.
*
* The Initial Developer of the Original Code is Sapient Corporation
*
* Copyright (C) 2003 Sapient Corporation. All Rights Reserved.
*/
package org.sape.carbon.services.perflog;
import java.util.EmptyStackException;
import java.util.Stack;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
/**
* <p>Provides performance logging (sometimes known as profiling) services to
* clients. PerfLogger can be used to time operations and log the time of said
* operations to the framework logging service.</p>
*
* <p>The actual timing is accomplished using a stack of objects passed into the
* start() method. The stack is kept in thread local storage, which
* removes any inter-thread coordination and synchronization issues.</p>
*
* <p>The times generated by the PerfLogger are elapsed-time, also known as
* human time. In a system where only one operation is run at a time, or the
* system is not heavily loaded this should closely approximate CPU time. Note
* though that times for the same operations can differ significantly based upon
* the load of the system.</p>
*
* <p>In order to maintain the sanity of the stack for performance measurements
* it is important that an end() method is actually executed for every start()
* method executed. As such, when exceptions are being caught and thrown it is
* recommended to structure code as follows:</p>
*
* <pre>
* public void myMethod() {
* String tracker = "MyClass.myMethod()"; // key for tracking
* PerfLogger.start(tracker);
* try {
* ....
* }
* catch (SomeException se) {
* ....
* }
* finally { PerfLogger.end(tracker); }
* }</pre>
*
* <p>Note that any object (not just Strings) can be passed to the start() and
* end() methods. This Object should, however, override the .equals() method to
* use something other than reference equality if there is a possibility that
* the start() and end() methods may receive different, but equal, objects.
* Using a custom object (instead of a String) can be useful to format the
* message placed into the performance log. The Object is toString()'d as part
* of the message logged in the end() method, and hence an object with several
* fields, and a custom toString() method can output a well structured message
* (perhaps containing classname, methodname and a list of parameters).</p>
*
* <p>
* In order to minimize performance impact of calls to the PerfLogger when
* performance logging is not desired, it is possible to indirectly enable and
* disable performance logging. Since PerfLogger uses the Carbon loggin
* subsystem it is able activate or deactivate based on whether the logging
* system is configured to utilize messages at INFO level from this service.
* </p>
*
* Copyright 2000-2003 Sapient
* @author Tim Fennell, December 2000
* @version $Revision: 1.10 $ ($Author: dvoet $)
*/
public class DefaultPerformanceLogger implements PerformanceLogger {
/**
* Provides a handle to apache-commons logger
*/
private Log log = LogFactory.getLog(this.getClass());
/** Used to indicate an invalid time for a performance measurement. */
public static final long INVALID_TIME = -1;
/**
* <p>Static member variable holding a reference to a ThreadLocal object.
* Contains the call stack (implemented as a java.util.Stack). A
* ThreadLocal object is a special object, which each Thread gets it's own
* copy of. Hence modifying the stack on one thread does not affect any
* other threads.</p>
*/
private final ThreadLocal threadLocalCallStack = new ThreadLocal();
/**
* <p>Utility method that returns a stack object kept in thread local
* storage. Used to lazily instantiate the stack and place it into the
* ThreadLocal storage.</p>
*
* @return stack object kept in thread local
*/
protected Stack getCallStack() {
Stack stack = (Stack) threadLocalCallStack.get();
// if the stack isn't initialized yet, then create one and dump it in
if (stack == null) {
stack = new Stack();
threadLocalCallStack.set(stack);
}
// return the stack
return stack;
}
/**
* <p>Starts a performance measurement. This is accomplished by placing
* the object into the stack with a timestamp. The object can then be
* retrieved, and the time taken for the operation calculated when
* end() is called.</p>
*
* <p>The object passed in can be any Object, and is not required to be a
* String. It is recommended to use Strings or subclasses of Object which
* override toString(). This is due to the fact that the object is
* written to the performance log using the toString() method.</p>
*
* @param trackedObject an object representing the operation
* being tracked.
*/
public void start(Object trackedObject) {
// Only update the performance stack if performance logging is on.
if (enabled()) {
getCallStack().push(new TrackingInfo(trackedObject));
}
}
/**
* <p>Ends a performance measurement. This is accomplished by finding the
* most recent item in the stack which matches the object passed in,
* according to the .equals() operation. This should usually be the item
* at the top of the stack, unless an error has occurred causing one or
* more end() calls to be skipped.</p>
*
* <p>It is recommended that if exceptions could be thrown during a
* performance measurement that the end() call be placed in a
* finally block to ensure that it is called. This will ensure proper
* operation of the PerfLogger.</p>
*
* <p>If the top most item in the stack does not match the one passed in,
* items are popped off the stack until a matching item is found, or the
* stack is empty. In the latter case, a time of PerfLogger.INVALID_TIME is
* returned, and a warning is entered into the performance log.</p>
*
* <p>On successful completion of a measurement, a message like the
* following is sent to the performance log:<br>
*
* <code>Performance measurement - tracked object {object.toString()}
* completed in #ms</code></p>
*
* @param trackedObject an object representing the operation
* being tracked. This must be equal (according to .equals())
* to the object passed in the corresponding call to
* start().
* @return long the time taken to complete the operation, or
* PerfLogger.INVALID_TIME if no matching object was found.
*/
public long end(Object trackedObject) {
// Some local variable needed to do the work
TrackingInfo currentTrackingInfo = null;
Object currentTrackedObject = null;
long endTime = DefaultPerformanceLogger.INVALID_TIME;
long totalTime = DefaultPerformanceLogger.INVALID_TIME;
Stack callStack = null;
// Track the end, only if performance logging is enabled.
if (enabled()) {
callStack = getCallStack();
// Take the end time now so that we don't include any of the time
// to find the right object and alter the stack.
endTime = System.currentTimeMillis();
try {
// Get the top most item from the call stack
currentTrackingInfo = (TrackingInfo) callStack.pop();
currentTrackedObject = currentTrackingInfo.getTrackedObject();
// Keep going down the call stack until we find the
// object that is being tracked. This is needed
// because methods may not call end() if the exit via
// exception. Recursive methods may not work well
// in exception cases...
while (!currentTrackedObject.equals(trackedObject)) {
currentTrackingInfo = (TrackingInfo) callStack.pop();
currentTrackedObject =
currentTrackingInfo.getTrackedObject();
}
totalTime = endTime - currentTrackingInfo.getStartTime();
trackTiming(trackedObject, totalTime);
} catch (EmptyStackException ese) {
// Log a message saying that we couldn't find the object in the
// call stack.
if (log.isWarnEnabled()) {
log.warn("Performance measurement - tracked object "
+ trackedObject
+ " could not be located. Call stack now empty.");
}
totalTime = DefaultPerformanceLogger.INVALID_TIME;
}
}
// Return the time since this track was started.
return totalTime;
}
/**
* <p>Clears the call stack, writing to the performance log information
* regarding what was in the stack at time of clearance.</p>
*
* @return <code>int</code> the depth of the stack before clearance.
*/
public int clearStack() {
// If performance logging is on, return the true size of the stack,
// otherwise return 0.
if (enabled()) {
int previousDepth = getCallStack().size();
logCallStack();
getCallStack().clear();
if (log.isTraceEnabled()) {
log.trace(
"Performance measurement stack being cleared on thread "
+ Thread.currentThread().getName());
}
return previousDepth;
} else {
return 0;
}
}
/**
* <p>Logs information regarding the current state of the performance stack
* to the performance log. Information logged is of the format:</p>
*
* <pre>Performance measurement stack logged on thread <threadName>
* Tracking stack (depth n):
* 0. item0.toString() [Started at ######ms]
* 1. item1.toString() [Started at ######ms]
* Current time is ######ms</pre>
*/
public void logCallStack() {
// Log the callstack only if performance logging is enabled.
if (enabled()) {
Stack stack = getCallStack();
StringBuffer message = new StringBuffer(256);
TrackingInfo info = null;
// Put some header info together, including the thread name and
// stack depth
message.append("Performance measurement stack logged on thread ");
message.append(Thread.currentThread().getName());
message.append("\n Tracking stack (depth ");
message.append(stack.size());
message.append("): \n");
// Add a little something for each entry in the stack
for (int i = 0; i < stack.size(); ++i) {
info = (TrackingInfo) stack.get(i);
message.append(" ");
if (i < 10) {
// a half-hearted attempt to align!
message.append(" ");
}
message.append(i);
message.append(": ");
message.append(info.getTrackedObject());
message.append(" [Started at ");
message.append(info.getStartTime());
message.append("ms]\n");
}
// Add a footnote with the current time in millis
message.append(" Current time is");
message.append(System.currentTimeMillis());
message.append("ms.");
log.info(message.toString());
}
}
/**
* Tracks the timing for a given object.
*
* @param trackedObject the object to track timing on.
* @param time the amount of time the object took.
*/
protected void trackTiming(Object trackedObject, long time) {
if (log.isInfoEnabled()) {
log.info("Performance measurement - item ["
+ trackedObject
+ "] executed in [" + time + "ms].");
}
}
/**
* <p>Determines if performance logging is enabled.</p>
* @return <code>boolean</code> true if performance logging is enabled,
* otherwise false.
*/
public boolean enabled() {
return log.isInfoEnabled();
}
}
|