LoggingStopWatch.java

package org.googlecode.perftrace.perf4j;

import org.googlecode.perftrace.PerfTrace;
import org.googlecode.perftrace.util.StringUtils;

/**
 * 
 * A LoggingStopWatch prevents the need to explicitly send the StopWatch string
 * to a Logger when stopping. Instead, all of the stop() and lap() methods
 * themselves are responsible for persisting the StopWatch:
 * 
 * <pre>
 * LoggingStopWatch stopWatch = new LoggingStopWatch();
 * ...some code
 * stopWatch.stop("codeBlock1"); //calling stop writes the StopWatch string to std err.
 * </pre>
 * 
 * This class just writes all StopWatch messages to the standard error stream,
 * but subclasses will use Loggers from various logging frameworks to persist
 * the StopWatch.
 * 
 * 
 */
@SuppressWarnings("serial")
public class LoggingStopWatch extends StopWatch {
	/**
	 * This threshold determines if a log call will be made. Only elapsed times
	 * greater than this amount will be logged.
	 */
	private long timeThreshold = 0L;

	/**
	 * Set this to true if both normal and slow suffixes should be appended to
	 * every StopWatch tag.
	 */
	private boolean normalAndSlowSuffixesEnabled = false;

	/**
	 * If normalAndSlowSuffixesEnabled == true then this suffix will be appended
	 * to the tag for elapsedTimes < timeThreshold. If
	 * normalAndSlowSuffixesEnabled == true and timeThreshold == 0 then this
	 * suffix will ALWAYS be appended to the tag.
	 */
	private String normalSuffix = "normal";

	/**
	 * If normalAndSlowSuffixesEnabled == true then this suffix will be appended
	 * to the tag for elapsedTimes >= timeThreshold. If
	 * normalAndSlowSuffixesEnabled == true and timeThreshold == 0 then this
	 * suffix will NEVER be appended to the tag.
	 */
	private String slowSuffix = "slow";

	private String successSuffix = "success";

	private String failureSuffix = "failure";

	private boolean successOrFailureFlag = true;

	private String logRetString;

	private boolean isRootMethod = false;

	private transient PerfTrace perftrace;

	// --- Constructors ---

	/**
	 * Creates a LoggingStopWatch with a blank tag, no message and started at
	 * the instant of creation.
	 */
	public LoggingStopWatch(PerfTrace perftrace) {
		this(false, perftrace);
	}

	public LoggingStopWatch(boolean isRootMethod, PerfTrace perftrace) {
		super();
		this.isRootMethod = isRootMethod;
		this.perftrace = perftrace;
		perftrace.addPerfWatch(this);
	}

	/**
	 * Creates a LoggingStopWatch with the specified tag, no message and started
	 * at the instant of creation.
	 * 
	 * @param tag
	 *            The tag name for this timing call. Tags are used to group
	 *            timing logs, thus each block of code being timed should have a
	 *            unique tag. Note that tags can take a hierarchical format
	 *            using dot notation.
	 */
	public LoggingStopWatch(String tag, PerfTrace perftrace) {
		this(tag, false, perftrace);
	}

	public LoggingStopWatch(String tag, boolean isRootMethod,
			PerfTrace perftrace) {
		super(tag);
		this.isRootMethod = isRootMethod;
		this.perftrace = perftrace;
		perftrace.addPerfWatch(this);
	}

	/**
	 * Creates a LoggingStopWatch with the specified tag and message, started an
	 * the instant of creation.
	 * 
	 * @param tag
	 *            The tag name for this timing call. Tags are used to group
	 *            timing logs, thus each block of code being timed should have a
	 *            unique tag. Note that tags can take a hierarchical format
	 *            using dot notation.
	 * @param message
	 *            Additional text to be printed with the logging statement of
	 *            this LoggingStopWatch.
	 */
	public LoggingStopWatch(String tag, String message, boolean isRootMethod,
			PerfTrace perftrace) {
		super(tag, message);
		this.isRootMethod = isRootMethod;
		this.perftrace = perftrace;
		perftrace.addPerfWatch(this);
	}

	/**
	 * Creates a LoggingStopWatch with a specified start and elapsed time, tag,
	 * and message. This constructor should normally not be called by third
	 * party code; it is intended to allow for deserialization of StopWatch
	 * logs.
	 * 
	 * @param startTime
	 *            The start time in milliseconds
	 * @param elapsedTime
	 *            The elapsed time in milliseconds
	 * @param tag
	 *            The tag used to group timing logs of the same code block
	 * @param message
	 *            Additional message text
	 */
	public LoggingStopWatch(long startTime, long elapsedTime, String tag,
			String message, boolean isRootMethod, PerfTrace perftrace) {
		super(startTime, elapsedTime, tag, message);
		this.isRootMethod = isRootMethod;
		this.perftrace = perftrace;
		perftrace.addPerfWatch(this);
	}

	// --- Bean Properties ---
	/**
	 * Gets a threshold level, in milliseconds, below which logging calls will
	 * not be made. Defaults to 0, meaning that the log method is always called
	 * on stop or lap regardless of the elapsed time.
	 * 
	 * @return The time threshold in milliseconds.
	 */
	public long getTimeThreshold() {
		return timeThreshold;
	}

	/**
	 * Sets a threshold level, in milliseconds, below which logging calls will
	 * not be made. You can set this to a high positive value if you only want
	 * logging to occur for abnormally slow execution times. Note, though, that
	 * you may wish to leave the threshold at 0 and attach a
	 * {@link org.perf4j.log4j.JmxAttributeStatisticsAppender} in the logging
	 * configuration to be notified when times are outside acceptable
	 * thresholds.
	 * 
	 * @param timeThreshold
	 *            The minimum elapsed time, in milliseconds, below which log
	 *            calls will not be made.
	 * @return this instance, for use with method chaining if desired
	 * @see org.perf4j.log4j.JmxAttributeStatisticsAppender#getNotificationThresholds()
	 */
	public LoggingStopWatch setTimeThreshold(long timeThreshold) {
		this.timeThreshold = timeThreshold;
		return this;
	}

	/**
	 * Determines whether or not to append normalSuffix or slowSuffix to every
	 * tag logged by this stopwatch.
	 * 
	 * @return whether or not to append normalSuffix or slowSuffix to every tag
	 *         logged by this stopwatch.
	 */
	public boolean isNormalAndSlowSuffixesEnabled() {
		return normalAndSlowSuffixesEnabled;
	}

	/**
	 * Sets whether to append normalSuffix and slowSuffix when timeThreshold
	 * > 0 AND elapsedTime >= timeThreshold
	 * 
	 * @param normalAndSlowSuffixesEnabled
	 *            true enables logging extra suffixes to normal and slow events;
	 *            false (default) suppresses the suffixes
	 */
	public LoggingStopWatch setNormalAndSlowSuffixesEnabled(
			boolean normalAndSlowSuffixesEnabled) {
		this.normalAndSlowSuffixesEnabled = normalAndSlowSuffixesEnabled;
		return this;
	}

	/**
	 * The suffix to append to the tag if normalAndSlowSuffixesEnabled=true and
	 * elapsedTime < timeThreshold and timeThreshold > 0. Default is
	 * ".normal".
	 * 
	 * @return the suffix to append if normalAndSlowSuffixesEnabled=true and the
	 *         event was normal and under the threshold
	 */
	public String getNormalSuffix() {
		return normalSuffix;
	}

	/**
	 * Sets the suffix to use when normalAndSlowSuffixesEnabled=true and
	 * timeThreshold > 0 and elapsedTime < timeThreshold. Setting this to
	 * "" is equivalent to setting to null.
	 * 
	 * @param normalSuffix
	 *            the suffix to append if normalAndSlowSuffixesEnabled and the
	 *            elapsedtime is under the threshold
	 */
	public LoggingStopWatch setNormalSuffix(String normalSuffix) {
		if (normalSuffix == null || "".equals(normalSuffix)) {
			throw new IllegalArgumentException(
					"normalSuffix cannot be blank. param=" + normalSuffix);
		}
		this.normalSuffix = normalSuffix;
		return this;
	}

	/**
	 * The suffix to append to the tag if normalAndSlowSuffixesEnabled=true and
	 * elapsedTime >= timeThreshold and timeThreshold > 0. Default is
	 * ".slow"
	 * 
	 * @return the suffix to append if normalAndSlowSuffixesEnabled=true and the
	 *         event was slow and over the threshold.
	 */
	public String getSlowSuffix() {
		return slowSuffix;
	}

	/**
	 * Sets the suffix to use when normalAndSlowSuffixesEnabled=true and
	 * timeThreshold > 0 and elapsedTime >= timeThreshold. Setting this to
	 * "" is equivalent to setting to null.
	 * 
	 * @param slowSuffix
	 *            the suffix to append if normalAndSlowSuffixesEnabled and the
	 *            elapsedtime is under the threshold
	 */
	public LoggingStopWatch setSlowSuffix(String slowSuffix) {
		if (slowSuffix == null || "".equals(slowSuffix)) {
			throw new IllegalArgumentException(
					"slowSuffix cannot be blank. param=" + slowSuffix);
		}
		this.slowSuffix = slowSuffix;
		return this;
	}

	public PerfTrace getPerftrace() {
		return perftrace;
	}

	public void setPerftrace(PerfTrace perftrace) {
		this.perftrace = perftrace;
	}

	public String getAdditionSeg() {
		String slowsuffix = isNormalAndSlowSuffixesEnabled()
				&& (getTimeThreshold() != 0)
				&& (getElapsedTime() >= getTimeThreshold()) ? getSlowSuffix()
				: getNormalSuffix();
		String failureOrSuccess = isSuccessOrFailureFlag() ? getSuccessSuffix()
				: getFailureSuffix();
		return String.format("[%s %s]", slowsuffix, failureOrSuccess);
	}

	// Just overridden to make use of covariant return types
	public LoggingStopWatch setTag(String tag) {
		super.setTag(tag);
		return this;
	}

	// Just overridden to make use of covariant return types
	public LoggingStopWatch setMessage(String message) {
		super.setMessage(message);
		return this;
	}

	public String getLogRetString() {
		return logRetString;
	}

	public void setLogRetString(String logRetString) {
		this.logRetString = logRetString;
	}

	public String getSuccessSuffix() {
		return successSuffix;
	}

	public void setSuccessSuffix(String successSuffix) {
		this.successSuffix = successSuffix;
	}

	public String getFailureSuffix() {
		return failureSuffix;
	}

	public void setFailureSuffix(String failureSuffix) {
		this.failureSuffix = failureSuffix;
	}

	public boolean isSuccessOrFailureFlag() {
		return successOrFailureFlag;
	}

	public void setSuccessOrFailureFlag(boolean successOrFailureFlag) {
		this.successOrFailureFlag = successOrFailureFlag;
	}

	public boolean isRootMethod() {
		return isRootMethod;
	}

	public void setRootMethod(boolean isRootMethod) {
		this.isRootMethod = isRootMethod;
	}

	// --- Stop/Lap/Helper Methods ---
	/**
	 * This stop method is overridden to perform the logging itself instead of
	 * needing to make a separate call to persist the timing information.
	 * 
	 * @return this.toString(), however, this should not be passed to a logger
	 *         as it will have already been logged.
	 */
	public String stop() {
		String retVal = StringUtils.join(new Object[] { super.stop(),
				getAdditionSeg() }, LOG_SEG);
		setLogRetString(retVal);
		doLogInternal(retVal, null);
		getPerftrace().watchStop(this);
		return retVal;
	}

	/**
	 * In cases where a code block terminated by throwing an exception, you may
	 * wish to have the exception logged in addition to the time it took to
	 * execute the block, in which case this method will write out the
	 * exception's stack trace in addition to the StopWatch timing method.
	 * 
	 * @param exception
	 *            The exception that was thrown by the timed code block
	 * @return this.toString(), however, this should not be passed to a logger
	 *         as it will have already been logged.
	 */
	public String stop(Throwable exception) {
		if (exception != null) {
			setSuccessOrFailureFlag(false);
			setMessage(getMessage()
					+ String.format("" + "[ExceptionMsg:%s]", exception
							.getMessage()));
		}
		return stop();
	}

	/**
	 * Identical to {@link #stop(String)}, but also allows you to specify an
	 * exception to be logged.
	 * 
	 * @param tag
	 *            The grouping tag for this StopWatch
	 * @param exception
	 *            The exception that was thrown by the timed code block
	 * @return this.toString(), however, this should not be passed to a logger
	 *         as it will have already been logged.
	 */
	public String stop(String tag, Throwable exception) {
		setTag(tag);
		return stop(exception);
	}

	/**
	 * Identical to {@link #stop(String, String)}, but also allows you to
	 * specify an exception to be logged.
	 * 
	 * @param tag
	 *            The grouping tag for this StopWatch
	 * @param message
	 *            A descriptive message about the timed block
	 * @param exception
	 *            The exception that was thrown by the timed code block
	 * @return this.toString(), however, this should not be passed to a logger
	 *         as it will have already been logged.
	 */
	public String stop(String tag, String message, Throwable exception) {
		setTag(tag);
		setMessage(message);
		return stop(exception);
	}

	/**
	 * Identical to {@link #lap(String)}, but also allows you to specify an
	 * exception to be logged.
	 * 
	 * @param tag
	 *            The grouping tag for the PREVIOUS code block that was timed.
	 * @param exception
	 *            The exception that was thrown by the timed code block.
	 * @return this.toString(), however, this should not be passed to a logger
	 *         as it will have already been logged.
	 */
	public String lap(String tag, Throwable exception) {
		String retVal = stop(tag, exception);
		start();
		return retVal;
	}

	/**
	 * Identical to {@link #lap(String, String)}, but also allows you to specify
	 * an exception to be logged.
	 * 
	 * @param tag
	 *            The grouping tag for the PREVIOUS code block that was timed.
	 * @param message
	 *            A descriptive message about the timed block
	 * @param exception
	 *            The exception that was thrown by the timed code block
	 * @return this.toString(), however, this should not be passed to a logger
	 *         as it will have already been logged.
	 */
	public String lap(String tag, String message, Throwable exception) {
		String retVal = stop(tag, message, exception);
		start();
		return retVal;
	}

	/**
	 * Determines whether or not logging is currently enabled for normal log
	 * messages for this StopWatch. This implementation always returns true, but
	 * subclasses should override this method if logging can be disabled. For
	 * example, a StopWatch that uses log4j Loggers will return false if the
	 * Logger is not currently enabled for the Level at which the log method is
	 * called.
	 * 
	 * @return true if calls to one of the stop() or lap() methods that do NOT
	 *         take an exception will result in the StopWatch being written to a
	 *         persisting log.
	 */
	public boolean isLogging() {
		return true;
	}

	// --- Template Methods ---
	/**
	 * This log method can be overridden by subclasses in order to persist the
	 * StopWatch, for example by using a log4j Logger. The default
	 * implementation here just writes the StopWatch to the standard error
	 * stream.
	 * 
	 * @param stopWatchAsString
	 *            The serialized StopWatch string
	 * @param exception
	 *            An exception, if any, that was also passed to the stop() or
	 *            lap() methods - may be null.
	 */
	protected void log(String stopWatchAsString, Throwable exception) {
		System.err.println(stopWatchAsString);
		if (exception != null) {
			exception.printStackTrace();
		}
	}

	public boolean isOverTimeThreshold() {
		long elapsedTime = getElapsedTime(); // to allow for subclasses to
		// override this value
		long timeThreshold = getTimeThreshold(); // to allow for subclasses to
		// override this value
		if (timeThreshold == 0 || elapsedTime >= timeThreshold)
			return true;
		return false;
	}

	// --- Object Methods ---

	public LoggingStopWatch clone() {
		return (LoggingStopWatch) super.clone();
	}

	// --- Private Methods ---
	// Helper method only calls log if elapsed time is greater than the time
	// threshold
	private void doLogInternal(String stopWatchAsString, Throwable exception) {
		// if normalAndSlowSuffixesEnabled then always log with the suffixes
		// added
		// getTag() should take care of appending the correct tag, and should
		// already be part of stopWatchAsString
		// Otherwise we default to the backward-compatible behavior: namely:
		// in most cases timeThreshold will be 0, so just short circuit out as
		// fast as possible
		// long elapsedTime = getElapsedTime(); // to allow for subclasses to
		// override this value
		// long timeThreshold = getTimeThreshold(); // to allow for subclasses
		// to
		// override this value
		if (isOverTimeThreshold()) {
			log(stopWatchAsString, exception);
		}
	}
}