org.sape.carbon.services.perflog
Class DefaultPerformanceLogger

java.lang.Object
  |
  +--org.sape.carbon.services.perflog.DefaultPerformanceLogger

All Implemented Interfaces:

FunctionalInterface, PerformanceLogger

Direct Known Subclasses:

BoundedBufferPerformanceLogger

public class DefaultPerformanceLogger

extends Object

implements PerformanceLogger

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.

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.

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.

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:

 public void myMethod() {
     String tracker = "MyClass.myMethod()"; // key for tracking
     PerfLogger.start(tracker);
     try {
        ....
     }
     catch (SomeException se) {
        ....
     }
     finally { PerfLogger.end(tracker); }
 }

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).

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.

Copyright 2000-2003 Sapient

Version:

$Revision: 1.10 $ ($Author: dvoet $)

Author:

Tim Fennell, December 2000

Field Summary

static long	INVALID_TIME Used to indicate an invalid time for a performance measurement.
private org.apache.commons.logging.Log	log Provides a handle to apache-commons logger
private ThreadLocal	threadLocalCallStack Static member variable holding a reference to a ThreadLocal object.

Constructor Summary

DefaultPerformanceLogger()

Method Summary

int	clearStack() Clears the call stack, writing to the performance log information regarding what was in the stack at time of clearance.
boolean	enabled() Determines if performance logging is enabled.
long	end(Object trackedObject) Ends a performance measurement.
protected Stack	getCallStack() Utility method that returns a stack object kept in thread local storage.
void	logCallStack() Logs information regarding the current state of the performance stack to the performance log.
void	start(Object trackedObject) Starts a performance measurement.
protected void	trackTiming(Object trackedObject, long time) Tracks the timing for a given object.

Methods inherited from class java.lang.Object

clone, equals, finalize, getClass, hashCode, notify, notifyAll, toString, wait, wait, wait

Field Detail

log

private org.apache.commons.logging.Log log

Provides a handle to apache-commons logger

INVALID_TIME

public static final long INVALID_TIME

Used to indicate an invalid time for a performance measurement.

See Also:

Constant Field Values

threadLocalCallStack

private final ThreadLocal threadLocalCallStack

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.

Constructor Detail

DefaultPerformanceLogger

public DefaultPerformanceLogger()

Method Detail

getCallStack

protected Stack getCallStack()

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.

Returns:

stack object kept in thread local

start

public void start(Object trackedObject)

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.

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.

Specified by:

start in interface PerformanceLogger

Parameters:

trackedObject - an object representing the operation being tracked.

end

public long end(Object trackedObject)

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.

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.

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.

On successful completion of a measurement, a message like the following is sent to the performance log:
Performance measurement - tracked object {object.toString()} completed in #ms

Specified by:

end in interface PerformanceLogger

Parameters:

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().

Returns:

long the time taken to complete the operation, or PerfLogger.INVALID_TIME if no matching object was found.

clearStack

public int clearStack()

Clears the call stack, writing to the performance log information regarding what was in the stack at time of clearance.

Returns:

int the depth of the stack before clearance.

logCallStack

public void logCallStack()

Logs information regarding the current state of the performance stack to the performance log. Information logged is of the format:

Performance measurement stack logged on thread 
        Tracking stack (depth n):
          0. item0.toString() [Started at ######ms]
          1. item1.toString() [Started at ######ms]
        Current time is ######ms

trackTiming

protected void trackTiming(Object trackedObject,
                           long time)

Tracks the timing for a given object.

Parameters:

trackedObject - the object to track timing on.

time - the amount of time the object took.

enabled

public boolean enabled()

Determines if performance logging is enabled.

Returns:

boolean true if performance logging is enabled, otherwise false.