Home | History | Annotate | Download | only in profiler 
      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ülcü
     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 stopwath 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 }
    263