Author: ceki Date: Sat May 3 21:45:11 2008 New Revision: 1681 Added: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopWatch/ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopWatch/DurationUnit.java logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopWatch/Profiler.java logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopWatch/StopWatch.java logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopWatch/Util.java Log: - ongoing work on StopWatch and poor man's profiler functionality Added: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopWatch/DurationUnit.java ============================================================================== --- (empty file) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopWatch/DurationUnit.java Sat May 3 21:45:11 2008 @@ -0,0 +1,5 @@ +package ch.qos.logback.classic.stopwatch; + +public enum DurationUnit { + NANOSECOND, MICROSECOND, MILLISSECOND, SECOND; +} \ No newline at end of file Added: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopWatch/Profiler.java ============================================================================== --- (empty file) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopWatch/Profiler.java Sat May 3 21:45:11 2008 @@ -0,0 +1,93 @@ +package ch.qos.logback.classic.stopwatch; + +import java.io.PrintStream; +import java.util.ArrayList; +import java.util.List; + +import ch.qos.logback.core.pattern.SpacePadder; + +/* + + Profiler [BAS] + |-- elapsed time [doX] 0 milliseconds. + |-- elapsed time [doYYYYY] 56 milliseconds. + |--+ Profiler Y + |-- elapsed time [doZ] 21 milliseconds. + |-- elapsed time [doZ] 21 milliseconds. + |-- Total elapsed time [Y] 78 milliseconds. + |-- elapsed time [doZ] 21 milliseconds. + |-- Total elapsed time [BAS] 78 milliseconds. +*/ + +public class Profiler { + + final static int MIN_SW_NAME_LENGTH = 10; + final static int MIN_SW_ELAPSED_TIME_NUMBER_LENGTH = 5; + + final String name; + final StopWatch globalStopWatch; + + List<StopWatch> stopwatchList = new ArrayList<StopWatch>(); + + public Profiler(String name) { + this.name = name; + this.globalStopWatch = new StopWatch(name); + } + + public void start(String name) { + stopLastStopWatch(); + StopWatch newSW = new StopWatch(name); + stopwatchList.add(newSW); + } + + StopWatch getLastStopWatch() { + if (stopwatchList.size() > 0) { + return stopwatchList.get(stopwatchList.size() - 1); + } else { + return null; + } + } + + void stopLastStopWatch() { + StopWatch last = getLastStopWatch(); + if (last != null) { + last.stop(); + } + } + + public void stop() { + stopLastStopWatch(); + globalStopWatch.stop(); + DurationUnit du = Util.selectDurationUnitForDisplay(globalStopWatch); + for (StopWatch sw : stopwatchList) { + printChildStopWatch(System.out, sw, du); + } + printGlobalSW(System.out, globalStopWatch, du); + } + + static void printChildStopWatch(PrintStream ps, StopWatch sw, DurationUnit du) { + StringBuffer buf = new StringBuffer(); + buf.append(" |-"); + buf.append(" elapsed time "); + SpacePadder.leftPad(buf, "["+sw.getName()+"]", MIN_SW_NAME_LENGTH); + buf.append(" "); + String timeStr = Util.durationInDunrationUnitsAsStr(sw.getResultInNanos(), du); + SpacePadder.leftPad(buf, timeStr, MIN_SW_ELAPSED_TIME_NUMBER_LENGTH); + buf.append(" "); + Util.appendDurationUnitAsStr(buf, du); + ps.println(buf.toString()); + } + + private static void printGlobalSW(PrintStream ps, StopWatch sw, DurationUnit du) { + StringBuffer buf = new StringBuffer(); + buf.append(" +-"); + buf.append(" Total elapsed time "); + SpacePadder.leftPad(buf, "["+sw.getName()+"]", MIN_SW_NAME_LENGTH); + buf.append(" "); + String timeStr = Util.durationInDunrationUnitsAsStr(sw.getResultInNanos(), du); + SpacePadder.leftPad(buf, timeStr, MIN_SW_ELAPSED_TIME_NUMBER_LENGTH); + buf.append(" "); + Util.appendDurationUnitAsStr(buf, du); + ps.println(buf.toString()); + } + +} Added: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopWatch/StopWatch.java ============================================================================== --- (empty file) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopWatch/StopWatch.java Sat May 3 21:45:11 2008 @@ -0,0 +1,68 @@ +package ch.qos.logback.classic.stopwatch; + + +public class StopWatch { + + + enum Status { + STARTED, STOPPED; + } + + final String name; + final long startTime; + long stopTime; + Status status; + + public StopWatch(String name) { + this.name = name; + this.startTime = System.nanoTime(); + this.status = Status.STARTED; + } + + public String getName() { + return name; + } + + public StopWatch stop() { + if(status == Status.STOPPED) { + return this; + } + return stop(System.nanoTime()); + } + + public StopWatch stop(long stopTime) { + this.status = Status.STOPPED; + this.stopTime = stopTime; + return this; + } + + @Override + public String toString() { + StringBuffer buf = new StringBuffer(); + buf.append("StopWatch ["); + buf.append(name); + buf.append("] "); + + switch (status) { + case STARTED: + buf.append("STARTED"); + break; + case STOPPED: + buf.append("elapsed time: "); + buf.append(Util.nanosInDurationUnitAsStr(this)); + break; + default: + new IllegalStateException("Status " + status + " is not expected"); + } + return buf.toString(); + } + + public final long getResultInNanos() { + if (status == Status.STARTED) { + return 0; + } else { + return stopTime - startTime; + } + } + +} Added: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopWatch/Util.java ============================================================================== --- (empty file) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/stopWatch/Util.java Sat May 3 21:45:11 2008 @@ -0,0 +1,81 @@ +package ch.qos.logback.classic.stopwatch; + +import java.text.DecimalFormat; + +class Util { + + static final long NANOS_IN_ONE_MICROSECOND = 1000; + static final long NANOS_IN_ONE_MILLISECOND = NANOS_IN_ONE_MICROSECOND * 1000; + static final long NANOS_IN_ONE_SECOND =NANOS_IN_ONE_MILLISECOND * 1000; + private static final DecimalFormat DECIMAL_FORMAT = new DecimalFormat("0.000"); + + static DurationUnit selectDurationUnitForDisplay(StopWatch sw) { + return selectDurationUnitForDisplay(sw.getResultInNanos()); + } + + static DurationUnit selectDurationUnitForDisplay(long durationInNanos) { + if (durationInNanos < 10*NANOS_IN_ONE_MICROSECOND) { + return DurationUnit.NANOSECOND; + } else if (durationInNanos < 10*NANOS_IN_ONE_MILLISECOND) { + return DurationUnit.MICROSECOND; + } else if (durationInNanos < NANOS_IN_ONE_SECOND) { + return DurationUnit.MILLISSECOND; + } else { + return DurationUnit.SECOND; + } + } + + static public long convertToMicros(long nanos) { + return nanos / NANOS_IN_ONE_MICROSECOND; + } + + static public long convertToMillis(long nanos) { + return nanos / NANOS_IN_ONE_MILLISECOND; + } + + static public double convertToSeconds(long nanos) { + return ((double) nanos / NANOS_IN_ONE_SECOND); + } + + static String durationInDunrationUnitsAsStr(StringBuffer buf, StopWatch sw) { + DurationUnit du = selectDurationUnitForDisplay(sw); + return durationInDunrationUnitsAsStr(sw.getResultInNanos(), du); + } + + static String durationInDunrationUnitsAsStr(long nanos, DurationUnit durationUnit) { + StringBuffer buf = new StringBuffer(); + switch (durationUnit) { + case NANOSECOND: + buf.append(nanos); + break; + case MICROSECOND: + buf.append(convertToMicros(nanos)); + break; + case MILLISSECOND: + buf.append(convertToMillis(nanos)); + break; + case SECOND: + double seconds = convertToSeconds(nanos); + buf.append(DECIMAL_FORMAT.format(seconds)); + break; + } + return buf.toString(); + } + + static void appendDurationUnitAsStr(StringBuffer buf, DurationUnit durationUnit) { + switch (durationUnit) { + case NANOSECOND: + buf.append("nanoseconds."); + break; + case MICROSECOND: + buf.append("microseconds."); + break; + case MILLISSECOND: + buf.append("milliseconds."); + break; + case SECOND: + buf.append(" seconds."); + break; + } + } +}