slf4j-ext/src/main/java/org/slf4j/profiler/Profiler.java

/* 
 * Copyright (c) 2004-2009 QOS.ch
 * All rights reserved.
 * 
 * Permission is hereby granted, free  of charge, to any person obtaining
 * a  copy  of this  software  and  associated  documentation files  (the
 * "Software"), to  deal in  the Software without  restriction, including
 * without limitation  the rights to  use, copy, modify,  merge, publish,
 * distribute,  sublicense, and/or sell  copies of  the Software,  and to
 * permit persons to whom the Software  is furnished to do so, subject to
 * the following conditions:
 * 
 * The  above  copyright  notice  and  this permission  notice  shall  be
 * included in all copies or substantial portions of the Software.
 * 
 * THE  SOFTWARE IS  PROVIDED  "AS  IS", WITHOUT  WARRANTY  OF ANY  KIND,
 * EXPRESS OR  IMPLIED, INCLUDING  BUT NOT LIMITED  TO THE  WARRANTIES OF
 * MERCHANTABILITY,    FITNESS    FOR    A   PARTICULAR    PURPOSE    AND
 * NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE
 * LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION
 * OF CONTRACT, TORT OR OTHERWISE,  ARISING FROM, OUT OF OR IN CONNECTION
 * WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
 */

package org.slf4j.profiler;

import java.util.ArrayList;
import java.util.List;

import org.slf4j.Logger;
import org.slf4j.Marker;
import org.slf4j.MarkerFactory;


// +  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.


/**
 * A poor man's profiler to measure the time elapsed performing some lengthy
 * task.
 * 
 * @author Ceki Gülcü
 */
public class Profiler implements TimeInstrument {

  final static String PROFILER_MARKER_NAME = "PROFILER";

  final static int MIN_SW_NAME_LENGTH = 24;
  final static int MIN_SW_ELAPSED_TIME_NUMBER_LENGTH = 9;

  final String name;
  final StopWatch globalStopWatch;

  List<TimeInstrument> childTimeInstrumentList = new ArrayList<TimeInstrument>();

  // optional field
  ProfilerRegistry profilerRegistry;
  // optional field
  Logger logger;

  public Profiler(String name) {
    this.name = name;
    this.globalStopWatch = new StopWatch(name);
  }

  public String getName() {
    return name;
  }

  public ProfilerRegistry getProfilerRegistry() {
    return profilerRegistry;
  }

  public void registerWith(ProfilerRegistry profilerRegistry) {
    if (profilerRegistry == null) {
      return;
    }
    this.profilerRegistry = profilerRegistry;
    profilerRegistry.put(this);
  }

  public Logger getLogger() {
    return logger;
  }

  public void setLogger(Logger logger) {
    this.logger = logger;
  }

  /**
   * Starts a child stop watch and stops any previously started time
   * instruments.
   */
  public void start(String name) {
    stopLastTimeInstrument();
    StopWatch childSW = new StopWatch(name);
    childTimeInstrumentList.add(childSW);
  }

  public Profiler startNested(String name) {
    stopLastTimeInstrument();
    Profiler nestedProfiler = new Profiler(name);
    nestedProfiler.registerWith(profilerRegistry);
    nestedProfiler.setLogger(logger);
    childTimeInstrumentList.add(nestedProfiler);
    return nestedProfiler;
  }

  TimeInstrument getLastTimeInstrument() {
    if (childTimeInstrumentList.size() > 0) {
      return childTimeInstrumentList.get(childTimeInstrumentList.size() - 1);
    } else {
      return null;
    }
  }

  void stopLastTimeInstrument() {
    TimeInstrument last = getLastTimeInstrument();
    if (last != null) {
      last.stop();
    }
  }

  // void stopNestedProfilers() {
  // for (Object child : childTimeInstrumentList) {
  // if (child instanceof Profiler)
  // ((Profiler) child).stop();
  // }
  // }

  public long elapsedTime() {
    return globalStopWatch.elapsedTime();
  }

  public TimeInstrument stop() {
    stopLastTimeInstrument();
    globalStopWatch.stop();
    return this;
  }

  public TimeInstrumentStatus getStatus() {
    return globalStopWatch.status;
  }

  /**
   * This method is used in tests.
   */
  void sanityCheck() throws IllegalStateException {
    if (getStatus() != TimeInstrumentStatus.STOPPED) {
      throw new IllegalStateException("time instrument [" + getName()
          + " is not stopped");
    }

    long totalElapsed = globalStopWatch.elapsedTime();
    long childTotal = 0;

    for (TimeInstrument ti : childTimeInstrumentList) {
      childTotal += ti.elapsedTime();
      if (ti.getStatus() != TimeInstrumentStatus.STOPPED) {
        throw new IllegalStateException("time instrument [" + ti.getName()
            + " is not stopped");
      }
      if (ti instanceof Profiler) {
        Profiler nestedProfiler = (Profiler) ti;
        nestedProfiler.sanityCheck();
      }
    }
    if (totalElapsed < childTotal) {
      throw new IllegalStateException(
          "children have a higher accumulated elapsed time");
    }
  }

  static String TOP_PROFILER_FIRST_PREFIX = "+";
  static String NESTED_PROFILER_FIRST_PREFIX = "|---+";
  static String TOTAL_ELAPSED = " Total        ";
  static String SUBTOTAL_ELAPSED = " Subtotal     ";
  static String ELAPSED_TIME = " elapsed time ";

  public void print() {
    System.out.println(toString());
  }

  @Override
  public String toString() {
    DurationUnit du = Util.selectDurationUnitForDisplay(globalStopWatch);
    return buildProfilerString(du, TOP_PROFILER_FIRST_PREFIX, TOTAL_ELAPSED, "");
  }

  public void log() {
    Marker profilerMarker = MarkerFactory.getMarker(PROFILER_MARKER_NAME);
    if (logger == null) {
      throw new NullPointerException(
          "If you invoke the log() method, then you must associate a logger with this profiler.");
    }
    if (logger.isDebugEnabled(profilerMarker)) {
      DurationUnit du = Util.selectDurationUnitForDisplay(globalStopWatch);
      String r = buildProfilerString(du, TOP_PROFILER_FIRST_PREFIX,
          TOTAL_ELAPSED, "");
      logger.debug(profilerMarker, SpacePadder.LINE_SEP + r);
    }
  }


  /**
   * Return a copy of the child instrument list for this Profiler instance.
   * 
   * @return a copy of this instance's child time instrument list
   * @since 1.5.9
   */
  public List<TimeInstrument> getCopyOfChildTimeInstruments() {
    List<TimeInstrument> copy = new ArrayList<TimeInstrument>(childTimeInstrumentList);
    return copy;
  }

  /**
   * Return a copy of the global stopwath of this Profiler instance.
   * 
   * @return a copy of this instance's global stop watch
   * @since 1.5.9
   */
  public StopWatch getCopyOfGlobalStopWatch() {
    StopWatch copy = new StopWatch(globalStopWatch);
    return copy;
  }
  
  private String buildProfilerString(DurationUnit du, String firstPrefix,
      String label, String indentation) {
    StringBuffer buf = new StringBuffer();

    buf.append(firstPrefix);
    buf.append(" Profiler [");
    buf.append(name);
    buf.append("]");
    buf.append(SpacePadder.LINE_SEP);
    for (TimeInstrument child : childTimeInstrumentList) {
      if (child instanceof StopWatch) {
        buildStopWatchString(buf, du, ELAPSED_TIME, indentation,
            (StopWatch) child);
      } else if (child instanceof Profiler) {
        Profiler profiler = (Profiler) child;
        String subString = profiler.buildProfilerString(du,
            NESTED_PROFILER_FIRST_PREFIX, SUBTOTAL_ELAPSED, indentation
                + "    ");
        buf.append(subString);
        buildStopWatchString(buf, du, ELAPSED_TIME, indentation,
            profiler.globalStopWatch);
      }
    }
    buildStopWatchString(buf, du, label, indentation, globalStopWatch);
    return buf.toString();
  }

  private static void buildStopWatchString(StringBuffer buf, DurationUnit du,
      String prefix, String indentation, StopWatch sw) {

    buf.append(indentation);
    buf.append("|--");
    buf.append(prefix);
    SpacePadder.leftPad(buf, "[" + sw.getName() + "]", MIN_SW_NAME_LENGTH);
    buf.append(" ");
    String timeStr = Util.durationInDurationUnitsAsStr(sw.elapsedTime(), du);
    SpacePadder.leftPad(buf, timeStr, MIN_SW_ELAPSED_TIME_NUMBER_LENGTH);
    buf.append(" ");
    Util.appendDurationUnitAsStr(buf, du);
    buf.append(SpacePadder.LINE_SEP);
  }
}