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ülcü
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<>();
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<>(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}