Profiler xref

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
    35  // +  Profiler [BAS]
    36  // |-- elapsed time            [doX]     0 milliseconds.
    37  // |-- elapsed time        [doYYYYY]    56 milliseconds.
    38  // |--+ Profiler Y
    39  //    |-- elapsed time            [doZ]    21 milliseconds.
    40  //    |-- elapsed time            [doZ]    21 milliseconds.
    41  //    |-- Total elapsed time        [Y]    78 milliseconds.
    42  // |-- elapsed time            [doZ]    21 milliseconds.
    43  // |-- Total elapsed time      [BAS]    78 milliseconds.
    44
    45
    46  /**
    47   * A poor man's profiler to measure the time elapsed performing some lengthy
    48   * task.
    49   *
    50   * @author Ceki G&uuml;lc&uuml;
    51   */
    52  public class Profiler implements TimeInstrument {
    53
    54    final static String PROFILER_MARKER_NAME = "PROFILER";
    55
    56    final static int MIN_SW_NAME_LENGTH = 24;
    57    final static int MIN_SW_ELAPSED_TIME_NUMBER_LENGTH = 9;
    58
    59    final String name;
    60    final StopWatch globalStopWatch;
    61
    62    List<TimeInstrument> childTimeInstrumentList = new ArrayList<TimeInstrument>();
    63
    64    // optional field
    65    ProfilerRegistry profilerRegistry;
    66    // optional field
    67    Logger logger;
    68
    69    public Profiler(String name) {
    70      this.name = name;
    71      this.globalStopWatch = new StopWatch(name);
    72    }
    73
    74    public String getName() {
    75      return name;
    76    }
    77
    78    public ProfilerRegistry getProfilerRegistry() {
    79      return profilerRegistry;
    80    }
    81
    82    public void registerWith(ProfilerRegistry profilerRegistry) {
    83      if (profilerRegistry == null) {
    84        return;
    85      }
    86      this.profilerRegistry = profilerRegistry;
    87      profilerRegistry.put(this);
    88    }
    89
    90    public Logger getLogger() {
    91      return logger;
    92    }
    93
    94    public void setLogger(Logger logger) {
    95      this.logger = logger;
    96    }
    97
    98    /**
    99     * Starts a child stop watch and stops any previously started time
    100    * instruments.
    101    */
    102   public void start(String name) {
    103     stopLastTimeInstrument();
    104     StopWatch childSW = new StopWatch(name);
    105     childTimeInstrumentList.add(childSW);
    106   }
    107
    108   public Profiler startNested(String name) {
    109     stopLastTimeInstrument();
    110     Profiler nestedProfiler = new Profiler(name);
    111     nestedProfiler.registerWith(profilerRegistry);
    112     nestedProfiler.setLogger(logger);
    113     childTimeInstrumentList.add(nestedProfiler);
    114     return nestedProfiler;
    115   }
    116
    117   TimeInstrument getLastTimeInstrument() {
    118     if (childTimeInstrumentList.size() > 0) {
    119       return childTimeInstrumentList.get(childTimeInstrumentList.size() - 1);
    120     } else {
    121       return null;
    122     }
    123   }
    124
    125   void stopLastTimeInstrument() {
    126     TimeInstrument last = getLastTimeInstrument();
    127     if (last != null) {
    128       last.stop();
    129     }
    130   }
    131
    132   // void stopNestedProfilers() {
    133   // for (Object child : childTimeInstrumentList) {
    134   // if (child instanceof Profiler)
    135   // ((Profiler) child).stop();
    136   // }
    137   // }
    138
    139   public long elapsedTime() {
    140     return globalStopWatch.elapsedTime();
    141   }
    142
    143   public TimeInstrument stop() {
    144     stopLastTimeInstrument();
    145     globalStopWatch.stop();
    146     return this;
    147   }
    148
    149   public TimeInstrumentStatus getStatus() {
    150     return globalStopWatch.status;
    151   }
    152
    153   /**
    154    * This method is used in tests.
    155    */
    156   void sanityCheck() throws IllegalStateException {
    157     if (getStatus() != TimeInstrumentStatus.STOPPED) {
    158       throw new IllegalStateException("time instrument [" + getName()
    159           + " is not stopped");
    160     }
    161
    162     long totalElapsed = globalStopWatch.elapsedTime();
    163     long childTotal = 0;
    164
    165     for (TimeInstrument ti : childTimeInstrumentList) {
    166       childTotal += ti.elapsedTime();
    167       if (ti.getStatus() != TimeInstrumentStatus.STOPPED) {
    168         throw new IllegalStateException("time instrument [" + ti.getName()
    169             + " is not stopped");
    170       }
    171       if (ti instanceof Profiler) {
    172         Profiler nestedProfiler = (Profiler) ti;
    173         nestedProfiler.sanityCheck();
    174       }
    175     }
    176     if (totalElapsed < childTotal) {
    177       throw new IllegalStateException(
    178           "children have a higher accumulated elapsed time");
    179     }
    180   }
    181
    182   static String TOP_PROFILER_FIRST_PREFIX = "+";
    183   static String NESTED_PROFILER_FIRST_PREFIX = "|---+";
    184   static String TOTAL_ELAPSED = " Total        ";
    185   static String SUBTOTAL_ELAPSED = " Subtotal     ";
    186   static String ELAPSED_TIME = " elapsed time ";
    187
    188   public void print() {
    189     System.out.println(toString());
    190   }
    191
    192   @Override
    193   public String toString() {
    194     DurationUnit du = Util.selectDurationUnitForDisplay(globalStopWatch);
    195     return buildProfilerString(du, TOP_PROFILER_FIRST_PREFIX, TOTAL_ELAPSED, "");
    196   }
    197
    198   public void log() {
    199     Marker profilerMarker = MarkerFactory.getMarker(PROFILER_MARKER_NAME);
    200     if (logger == null) {
    201       throw new NullPointerException(
    202           "If you invoke the log() method, then you must associate a logger with this profiler.");
    203     }
    204     if (logger.isDebugEnabled(profilerMarker)) {
    205       DurationUnit du = Util.selectDurationUnitForDisplay(globalStopWatch);
    206       String r = buildProfilerString(du, TOP_PROFILER_FIRST_PREFIX,
    207           TOTAL_ELAPSED, "");
    208       logger.debug(profilerMarker, SpacePadder.LINE_SEP + r);
    209     }
    210   }
    211
    212
    213   /**
    214    * Return a copy of the child instrument list for this Profiler instance.
    215    *
    216    * @return a copy of this instance's child time instrument list
    217    * @since 1.5.9
    218    */
    219   public List<TimeInstrument> getCopyOfChildTimeInstruments() {
    220     List<TimeInstrument> copy = new ArrayList<TimeInstrument>(childTimeInstrumentList);
    221     return copy;
    222   }
    223
    224   /**
    225    * Return a copy of the global stopwath of this Profiler instance.
    226    *
    227    * @return a copy of this instance's global stop watch
    228    * @since 1.5.9
    229    */
    230   public StopWatch getCopyOfGlobalStopWatch() {
    231     StopWatch copy = new StopWatch(globalStopWatch);
    232     return copy;
    233   }
    234
    235   private String buildProfilerString(DurationUnit du, String firstPrefix,
    236       String label, String indentation) {
    237     StringBuffer buf = new StringBuffer();
    238
    239     buf.append(firstPrefix);
    240     buf.append(" Profiler [");
    241     buf.append(name);
    242     buf.append("]");
    243     buf.append(SpacePadder.LINE_SEP);
    244     for (TimeInstrument child : childTimeInstrumentList) {
    245       if (child instanceof StopWatch) {
    246         buildStopWatchString(buf, du, ELAPSED_TIME, indentation,
    247             (StopWatch) child);
    248       } else if (child instanceof Profiler) {
    249         Profiler profiler = (Profiler) child;
    250         String subString = profiler.buildProfilerString(du,
    251             NESTED_PROFILER_FIRST_PREFIX, SUBTOTAL_ELAPSED, indentation
    252                 + "    ");
    253         buf.append(subString);
    254         buildStopWatchString(buf, du, ELAPSED_TIME, indentation,
    255             profiler.globalStopWatch);
    256       }
    257     }
    258     buildStopWatchString(buf, du, label, indentation, globalStopWatch);
    259     return buf.toString();
    260   }
    261
    262   private static void buildStopWatchString(StringBuffer buf, DurationUnit du,
    263       String prefix, String indentation, StopWatch sw) {
    264
    265     buf.append(indentation);
    266     buf.append("|--");
    267     buf.append(prefix);
    268     SpacePadder.leftPad(buf, "[" + sw.getName() + "]", MIN_SW_NAME_LENGTH);
    269     buf.append(" ");
    270     String timeStr = Util.durationInDurationUnitsAsStr(sw.elapsedTime(), du);
    271     SpacePadder.leftPad(buf, timeStr, MIN_SW_ELAPSED_TIME_NUMBER_LENGTH);
    272     buf.append(" ");
    273     Util.appendDurationUnitAsStr(buf, du);
    274     buf.append(SpacePadder.LINE_SEP);
    275   }
    276 }