View Javadoc

    1   /**
    2    * Copyright (c) 2004-2011 QOS.ch
    3    * All rights reserved.
    4    *
    5    * Permission is hereby granted, free  of charge, to any person obtaining
    6    * a  copy  of this  software  and  associated  documentation files  (the
    7    * "Software"), to  deal in  the Software without  restriction, including
    8    * without limitation  the rights to  use, copy, modify,  merge, publish,
    9    * distribute,  sublicense, and/or sell  copies of  the Software,  and to
    10   * permit persons to whom the Software  is furnished to do so, subject to
    11   * the following conditions:
    12   *
    13   * The  above  copyright  notice  and  this permission  notice  shall  be
    14   * included in all copies or substantial portions of the Software.
    15   *
    16   * THE  SOFTWARE IS  PROVIDED  "AS  IS", WITHOUT  WARRANTY  OF ANY  KIND,
    17   * EXPRESS OR  IMPLIED, INCLUDING  BUT NOT LIMITED  TO THE  WARRANTIES OF
    18   * MERCHANTABILITY,    FITNESS    FOR    A   PARTICULAR    PURPOSE    AND
    19   * NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE
    20   * LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION
    21   * OF CONTRACT, TORT OR OTHERWISE,  ARISING FROM, OUT OF OR IN CONNECTION
    22   * WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
    23   *
    24   */
    25  package org.slf4j.profiler;
    26
    27  import java.util.ArrayList;
    28  import java.util.List;
    29
    30  import org.slf4j.Logger;
    31  import org.slf4j.Marker;
    32  import org.slf4j.MarkerFactory;
    33
    34  // +  Profiler [BAS]
    35  // |-- elapsed time            [doX]     0 milliseconds.
    36  // |-- elapsed time        [doYYYYY]    56 milliseconds.
    37  // |--+ Profiler Y
    38  //    |-- elapsed time            [doZ]    21 milliseconds.
    39  //    |-- elapsed time            [doZ]    21 milliseconds.
    40  //    |-- Total elapsed time        [Y]    78 milliseconds.
    41  // |-- elapsed time            [doZ]    21 milliseconds.
    42  // |-- Total elapsed time      [BAS]    78 milliseconds.
    43
    44  /**
    45   * A poor man's profiler to measure the time elapsed performing some lengthy
    46   * task.
    47   *
    48   * @author Ceki G&uuml;lc&uuml;
    49   */
    50  public class Profiler implements TimeInstrument {
    51
    52      final static String PROFILER_MARKER_NAME = "PROFILER";
    53
    54      final static int MIN_SW_NAME_LENGTH = 24;
    55      final static int MIN_SW_ELAPSED_TIME_NUMBER_LENGTH = 9;
    56
    57      final String name;
    58      final StopWatch globalStopWatch;
    59
    60      List<TimeInstrument> childTimeInstrumentList = new ArrayList<TimeInstrument>();
    61
    62      // optional field
    63      ProfilerRegistry profilerRegistry;
    64      // optional field
    65      Logger logger;
    66
    67      public Profiler(String name) {
    68          this.name = name;
    69          this.globalStopWatch = new StopWatch(name);
    70      }
    71
    72      public String getName() {
    73          return name;
    74      }
    75
    76      public ProfilerRegistry getProfilerRegistry() {
    77          return profilerRegistry;
    78      }
    79
    80      public void registerWith(ProfilerRegistry profilerRegistry) {
    81          if (profilerRegistry == null) {
    82              return;
    83          }
    84          this.profilerRegistry = profilerRegistry;
    85          profilerRegistry.put(this);
    86      }
    87
    88      public Logger getLogger() {
    89          return logger;
    90      }
    91
    92      public void setLogger(Logger logger) {
    93          this.logger = logger;
    94      }
    95
    96      /**
    97       * Starts a child stop watch and stops any previously started time
    98       * instruments.
    99       */
    100     public void start(String name) {
    101         stopLastTimeInstrument();
    102         StopWatch childSW = new StopWatch(name);
    103         childTimeInstrumentList.add(childSW);
    104     }
    105
    106     public Profiler startNested(String name) {
    107         stopLastTimeInstrument();
    108         Profiler nestedProfiler = new Profiler(name);
    109         nestedProfiler.registerWith(profilerRegistry);
    110         nestedProfiler.setLogger(logger);
    111         childTimeInstrumentList.add(nestedProfiler);
    112         return nestedProfiler;
    113     }
    114
    115     TimeInstrument getLastTimeInstrument() {
    116         if (childTimeInstrumentList.size() > 0) {
    117             return childTimeInstrumentList.get(childTimeInstrumentList.size() - 1);
    118         } else {
    119             return null;
    120         }
    121     }
    122
    123     void stopLastTimeInstrument() {
    124         TimeInstrument last = getLastTimeInstrument();
    125         if (last != null) {
    126             last.stop();
    127         }
    128     }
    129
    130     // void stopNestedProfilers() {
    131     // for (Object child : childTimeInstrumentList) {
    132     // if (child instanceof Profiler)
    133     // ((Profiler) child).stop();
    134     // }
    135     // }
    136
    137     public long elapsedTime() {
    138         return globalStopWatch.elapsedTime();
    139     }
    140
    141     public TimeInstrument stop() {
    142         stopLastTimeInstrument();
    143         globalStopWatch.stop();
    144         return this;
    145     }
    146
    147     public TimeInstrumentStatus getStatus() {
    148         return globalStopWatch.status;
    149     }
    150
    151     /**
    152      * This method is used in tests.
    153      */
    154     void sanityCheck() throws IllegalStateException {
    155         if (getStatus() != TimeInstrumentStatus.STOPPED) {
    156             throw new IllegalStateException("time instrument [" + getName() + " is not stopped");
    157         }
    158
    159         long totalElapsed = globalStopWatch.elapsedTime();
    160         long childTotal = 0;
    161
    162         for (TimeInstrument ti : childTimeInstrumentList) {
    163             childTotal += ti.elapsedTime();
    164             if (ti.getStatus() != TimeInstrumentStatus.STOPPED) {
    165                 throw new IllegalStateException("time instrument [" + ti.getName() + " is not stopped");
    166             }
    167             if (ti instanceof Profiler) {
    168                 Profiler nestedProfiler = (Profiler) ti;
    169                 nestedProfiler.sanityCheck();
    170             }
    171         }
    172         if (totalElapsed < childTotal) {
    173             throw new IllegalStateException("children have a higher accumulated elapsed time");
    174         }
    175     }
    176
    177     static String TOP_PROFILER_FIRST_PREFIX = "+";
    178     static String NESTED_PROFILER_FIRST_PREFIX = "|---+";
    179     static String TOTAL_ELAPSED = " Total        ";
    180     static String SUBTOTAL_ELAPSED = " Subtotal     ";
    181     static String ELAPSED_TIME = " elapsed time ";
    182
    183     public void print() {
    184         System.out.println(toString());
    185     }
    186
    187     @Override
    188     public String toString() {
    189         DurationUnit du = Util.selectDurationUnitForDisplay(globalStopWatch);
    190         return buildProfilerString(du, TOP_PROFILER_FIRST_PREFIX, TOTAL_ELAPSED, "");
    191     }
    192
    193     public void log() {
    194         Marker profilerMarker = MarkerFactory.getMarker(PROFILER_MARKER_NAME);
    195         if (logger == null) {
    196             throw new NullPointerException("If you invoke the log() method, then you must associate a logger with this profiler.");
    197         }
    198         if (logger.isDebugEnabled(profilerMarker)) {
    199             DurationUnit du = Util.selectDurationUnitForDisplay(globalStopWatch);
    200             String r = buildProfilerString(du, TOP_PROFILER_FIRST_PREFIX, TOTAL_ELAPSED, "");
    201             logger.debug(profilerMarker, SpacePadder.LINE_SEP + r);
    202         }
    203     }
    204
    205     /**
    206      * Return a copy of the child instrument list for this Profiler instance.
    207      *
    208      * @return a copy of this instance's child time instrument list
    209      * @since 1.5.9
    210      */
    211     public List<TimeInstrument> getCopyOfChildTimeInstruments() {
    212         List<TimeInstrument> copy = new ArrayList<TimeInstrument>(childTimeInstrumentList);
    213         return copy;
    214     }
    215
    216     /**
    217      * Return a copy of the global stopwatch of this Profiler instance.
    218      *
    219      * @return a copy of this instance's global stop watch
    220      * @since 1.5.9
    221      */
    222     public StopWatch getCopyOfGlobalStopWatch() {
    223         StopWatch copy = new StopWatch(globalStopWatch);
    224         return copy;
    225     }
    226
    227     private String buildProfilerString(DurationUnit du, String firstPrefix, String label, String indentation) {
    228         StringBuilder buf = new StringBuilder();
    229
    230         buf.append(firstPrefix);
    231         buf.append(" Profiler [");
    232         buf.append(name);
    233         buf.append("]");
    234         buf.append(SpacePadder.LINE_SEP);
    235         for (TimeInstrument child : childTimeInstrumentList) {
    236             if (child instanceof StopWatch) {
    237                 buildStopWatchString(buf, du, ELAPSED_TIME, indentation, (StopWatch) child);
    238             } else if (child instanceof Profiler) {
    239                 Profiler profiler = (Profiler) child;
    240                 String subString = profiler.buildProfilerString(du, NESTED_PROFILER_FIRST_PREFIX, SUBTOTAL_ELAPSED, indentation + "    ");
    241                 buf.append(subString);
    242                 buildStopWatchString(buf, du, ELAPSED_TIME, indentation, profiler.globalStopWatch);
    243             }
    244         }
    245         buildStopWatchString(buf, du, label, indentation, globalStopWatch);
    246         return buf.toString();
    247     }
    248
    249     private static void buildStopWatchString(StringBuilder buf, DurationUnit du, String prefix, String indentation, StopWatch sw) {
    250
    251         buf.append(indentation);
    252         buf.append("|--");
    253         buf.append(prefix);
    254         SpacePadder.leftPad(buf, "[" + sw.getName() + "]", MIN_SW_NAME_LENGTH);
    255         buf.append(" ");
    256         String timeStr = Util.durationInDurationUnitsAsStr(sw.elapsedTime(), du);
    257         SpacePadder.leftPad(buf, timeStr, MIN_SW_ELAPSED_TIME_NUMBER_LENGTH);
    258         buf.append(" ");
    259         Util.appendDurationUnitAsStr(buf, du);
    260         buf.append(SpacePadder.LINE_SEP);
    261     }
    262 }