    001/**
    002 * Copyright (c) 2004-2011 QOS.ch
    003 * All rights reserved.
    004 *
    005 * Permission is hereby granted, free  of charge, to any person obtaining
    006 * a  copy  of this  software  and  associated  documentation files  (the
    007 * "Software"), to  deal in  the Software without  restriction, including
    008 * without limitation  the rights to  use, copy, modify,  merge, publish,
    009 * distribute,  sublicense, and/or sell  copies of  the Software,  and to
    010 * permit persons to whom the Software  is furnished to do so, subject to
    011 * the following conditions:
    012 *
    013 * The  above  copyright  notice  and  this permission  notice  shall  be
    014 * included in all copies or substantial portions of the Software.
    015 *
    016 * THE  SOFTWARE IS  PROVIDED  "AS  IS", WITHOUT  WARRANTY  OF ANY  KIND,
    017 * EXPRESS OR  IMPLIED, INCLUDING  BUT NOT LIMITED  TO THE  WARRANTIES OF
    018 * MERCHANTABILITY,    FITNESS    FOR    A   PARTICULAR    PURPOSE    AND
    019 * NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE
    020 * LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION
    021 * OF CONTRACT, TORT OR OTHERWISE,  ARISING FROM, OUT OF OR IN CONNECTION
    022 * WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
    023 *
    024 */
    025package org.slf4j.profiler;
    026
    027import java.util.ArrayList;
    028import java.util.List;
    029
    030import org.slf4j.Logger;
    031import org.slf4j.Marker;
    032import org.slf4j.MarkerFactory;
    033
    034// +  Profiler [BAS]
    035// |-- elapsed time            [doX]     0 milliseconds.
    036// |-- elapsed time        [doYYYYY]    56 milliseconds.
    037// |--+ Profiler Y
    038//    |-- elapsed time            [doZ]    21 milliseconds.
    039//    |-- elapsed time            [doZ]    21 milliseconds.
    040//    |-- Total elapsed time        [Y]    78 milliseconds.
    041// |-- elapsed time            [doZ]    21 milliseconds.
    042// |-- Total elapsed time      [BAS]    78 milliseconds.
    043
    044/**
    045 * A poor man's profiler to measure the time elapsed performing some lengthy
    046 * task.
    047 *
    048 * @author Ceki G&uuml;lc&uuml;
    049 */
    050public class Profiler implements TimeInstrument {
    051
    052    final static String PROFILER_MARKER_NAME = "PROFILER";
    053
    054    final static int MIN_SW_NAME_LENGTH = 24;
    055    final static int MIN_SW_ELAPSED_TIME_NUMBER_LENGTH = 9;
    056
    057    final String name;
    058    final StopWatch globalStopWatch;
    059
    060    List<TimeInstrument> childTimeInstrumentList = new ArrayList<TimeInstrument>();
    061
    062    // optional field
    063    ProfilerRegistry profilerRegistry;
    064    // optional field
    065    Logger logger;
    066
    067    public Profiler(String name) {
    068        this.name = name;
    069        this.globalStopWatch = new StopWatch(name);
    070    }
    071
    072    public String getName() {
    073        return name;
    074    }
    075
    076    public ProfilerRegistry getProfilerRegistry() {
    077        return profilerRegistry;
    078    }
    079
    080    public void registerWith(ProfilerRegistry profilerRegistry) {
    081        if (profilerRegistry == null) {
    082            return;
    083        }
    084        this.profilerRegistry = profilerRegistry;
    085        profilerRegistry.put(this);
    086    }
    087
    088    public Logger getLogger() {
    089        return logger;
    090    }
    091
    092    public void setLogger(Logger logger) {
    093        this.logger = logger;
    094    }
    095
    096    /**
    097     * Starts a child stop watch and stops any previously started time
    098     * instruments.
    099     */
    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}