package org.googlecode.perftrace.perf4j; import java.io.Serializable; import java.util.concurrent.Executors; import java.util.concurrent.ScheduledExecutorService; import java.util.concurrent.ThreadFactory; import java.util.concurrent.TimeUnit; import org.googlecode.perftrace.util.StringUtils; /** * The StopWatch class is used to time code blocks in Perf4J. The general usage * pattern is to create a StopWatch before a section of code that is to be timed * and then stop it before it is passed to a logging method: * <p/> * * <pre> * StopWatch stopWatch = new StopWatch(); * try { * ...code being timed... * log.info(stopWatch.stop("methodBeingTimed.success")); * } catch (Exception e) { * log.error(stopWatch.stop("methodBeingTimed.fail"), e); * } * </pre> * <p/> * Note that a StopWatch is reusable. That is, you can call <tt>start()</tt> and * <tt>stop()</tt> in succession and the <tt>getElapsedTime()</tt> method will * refer to the time since the most recent <tt>start()</tt> call. * <p/> * In general, most clients will find it simpler and cleaner to use the * {@link LoggingStopWatch} class or one of its subclasses in preference to this * class. * */ public class StopWatch implements Serializable, Cloneable { private static final long serialVersionUID = 8453041765823416495L; public static final String DEFAULT_LOGGER_NAME = "org.googlecode.perftrace.TimingLogger"; private static final long NANOS_IN_A_MILLI = 1000000L; /** * toString 方法字段分隔符 */ public static final String LOG_SEG = "@"; private long startTime; private long nanoStartTime; private long nanoEndTime; private long elapsedTime; private String tag; private String message; /** * Creates a StopWatch with a blank tag, no message and started at the * instant of creation. */ public StopWatch() { this("", null); } /** * Creates a StopWatch 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 StopWatch(String tag) { this(tag, null); } /** * Creates a StopWatch 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 StopWatch. */ public StopWatch(String tag, String message) { this(SystemTimer.currentTimeMillis(), -1L, tag, message); } /** * Creates a StopWatch 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 StopWatch(long startTime, long elapsedTime, String tag, String message) { this.startTime = startTime; this.nanoStartTime = (elapsedTime == -1L) ? System.nanoTime() : -1L; this.elapsedTime = elapsedTime; this.tag = tag; this.message = message; } // --- Bean Properties --- /** * Gets the time when this instance was created, or when one of the * <tt>start()</tt> messages was last called. * * @return The start time in milliseconds since the epoch. */ public long getStartTime() { return startTime; } /** * Gets the time in milliseconds between when this StopWatch was last * started and stopped. Is <tt>stop()</tt> was not called, then the time * returned is the time since the StopWatch was started. * * @return The elapsed time in milliseconds. */ public long getElapsedTime() { return (elapsedTime == -1L) ? (System.nanoTime() - nanoStartTime) / NANOS_IN_A_MILLI : elapsedTime; } /** * Gets the tag used to group this StopWatch instance with other instances * used to time the same code block. * * @return The grouping tag. */ public String getTag() { return tag; } /** * Sets the grouping tag for this StopWatch instance. * * @param tag * The grouping tag. * @return this instance, for method chaining if desired */ public StopWatch setTag(String tag) { this.tag = tag; return this; } /** * Gets any additional message that was set on this StopWatch instance. * * @return The message associated with this StopWatch, which may be null. */ public String getMessage() { if (message == null) message = "N"; return message; } /** * Sends a message on this StopWatch instance to be printed when this * instance is logged. * * @param message * The message associated with this StopWatch, which may be null. * @return this instance, for method chaining if desired. */ public StopWatch setMessage(String message) { this.message = message; return this; } public long getNanoStartTime() { return nanoStartTime; } public long getNanoEndTime() { return nanoEndTime; } // --- Start/Stop/Lap methods --- /** * Starts this StopWatch, which sets its startTime property to the current * time and resets the elapsedTime property. For single-use StopWatch * instance you should not need to call this method as a StopWatch is * automatically started when it is created. Note any existing tag and * message are not changed. */ public void start() { startTime = SystemTimer.currentTimeMillis(); nanoStartTime = System.nanoTime(); elapsedTime = -1L; } /** * Starts this StopWatch and sets its tag to the specified value. For * single-use StopWatch instance you should not need to call this method as * a StopWatch is automatically started when it is created. Note any * existing message on this StopWatch is not changed. * * @param tag * The grouping tag for this StopWatch */ public void start(String tag) { start(); this.tag = tag; } /** * Starts this StopWatch and sets its tag and message to the specified * values. For single-use StopWatch instance you should not need to call * this method as a StopWatch is automatically started when it is created. * * @param tag * The grouping tag for this StopWatch * @param message * A descriptive message about the code being timed, may be null */ public void start(String tag, String message) { start(); this.tag = tag; this.message = message; } /** * Stops this StopWatch, which "freezes" its elapsed time. You should * normally call this method (or one of the other stop methods) before * passing this instance to a logger. * * @return this.toString(), which is a message suitable for logging */ public String stop() { this.nanoEndTime = System.nanoTime(); elapsedTime = (nanoEndTime - nanoStartTime) / NANOS_IN_A_MILLI; return this.toString(); } /** * Stops this StopWatch and sets its grouping tag. * * @param tag * The grouping tag for this StopWatch * @return this.toString(), which is a message suitable for logging */ public String stop(String tag) { this.tag = tag; return stop(); } /** * Stops this StopWatch and sets its grouping tag and message. * * @param tag * The grouping tag for this StopWatch * @param message * A descriptive message about the code being timed, may be null * @return this.toString(), which is a message suitable for logging */ public String stop(String tag, String message) { this.tag = tag; this.message = message; return stop(); } /** * The lap method is useful when using a single StopWatch to time multiple * consecutive blocks. It calls stop() and then immediately calls start(), * e.g.: * <p/> * * <pre> * StopWatch stopWatch = new StopWatch(); * ...some code * log.info(stopWatch.lap("block1")); * ...some more code * log.info(stopWatch.lap("block2")); * ...even more code * log.info(stopWatch.stop("block3")); * </pre> * * @param tag * The grouping tag to use for the execution block that was just * stopped. * @return A message suitable for logging the previous execution block's * execution time. */ public String lap(String tag) { String retVal = stop(tag); start(); return retVal; } /** * The lap method is useful when using a single StopWatch to time multiple * consecutive blocks. It calls stop() and then immediately calls start(), * e.g.: * <p/> * * <pre> * StopWatch stopWatch = new StopWatch(); * ...some code * log.info(stopWatch.lap("block1", "message about block 1")); * ...some more code * log.info(stopWatch.lap("block2", "message about block 2")); * ...even more code * log.info(stopWatch.stop("block3", "message about block 3")); * </pre> * * @param tag * The grouping tag to use for the execution block that was just * stopped. * @param message * A descriptive message about the code being timed, may be null * @return A message suitable for logging the previous execution block's * execution time. */ public String lap(String tag, String message) { String retVal = stop(tag, message); start(); return retVal; } /** * 时间缓存 * * @author zhongfeng * */ public static class SystemTimer { private final static ScheduledExecutorService executor = Executors .newSingleThreadScheduledExecutor(new ThreadFactory() { @Override public Thread newThread(Runnable runnable) { Thread thread = new Thread(runnable, "System Clock"); thread.setDaemon(true); return thread; } }); private static final long tickUnit = Long.parseLong(System.getProperty( "notify.systimer.tick", "20")); static { executor.scheduleAtFixedRate(new TimerTicker(), tickUnit, tickUnit, TimeUnit.MILLISECONDS); Runtime.getRuntime().addShutdownHook(new Thread() { @Override public void run() { executor.shutdown(); } }); } private static volatile long time = System.currentTimeMillis(); private static class TimerTicker implements Runnable { public void run() { time = System.currentTimeMillis(); } } public static long currentTimeMillis() { return time; } } // --- Object Methods --- public String toString() { return StringUtils.join(new Object[] { getTag(), getStartTime(), getElapsedTime(), getNanoStartTime(), getNanoEndTime(), getMessage() }, LOG_SEG); } public StopWatch clone() { try { return (StopWatch) super.clone(); } catch (CloneNotSupportedException cnse) { throw new Error("Unexpected CloneNotSupportedException"); } } public boolean equals(Object o) { if (this == o) { return true; } if (!(o instanceof StopWatch)) { return false; } StopWatch stopWatch = (StopWatch) o; if (elapsedTime != stopWatch.elapsedTime) { return false; } if (startTime != stopWatch.startTime) { return false; } if (nanoStartTime != stopWatch.nanoStartTime) { return false; } if (message != null ? !message.equals(stopWatch.message) : stopWatch.message != null) { return false; } if (tag != null ? !tag.equals(stopWatch.tag) : stopWatch.tag != null) { return false; } return true; } public int hashCode() { int result = (int) (startTime ^ (startTime >>> 32)); result = 31 * result + (int) (nanoStartTime ^ (nanoStartTime >>> 32)); result = 31 * result + (int) (elapsedTime ^ (elapsedTime >>> 32)); result = 31 * result + (tag != null ? tag.hashCode() : 0); result = 31 * result + (message != null ? message.hashCode() : 0); return result; } }