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 
Profiler(String name)67     public Profiler(String name) {
68         this.name = name;
69         this.globalStopWatch = new StopWatch(name);
70     }
71 
getName()72     public String getName() {
73         return name;
74     }
75 
getProfilerRegistry()76     public ProfilerRegistry getProfilerRegistry() {
77         return profilerRegistry;
78     }
79 
registerWith(ProfilerRegistry profilerRegistry)80     public void registerWith(ProfilerRegistry profilerRegistry) {
81         if (profilerRegistry == null) {
82             return;
83         }
84         this.profilerRegistry = profilerRegistry;
85         profilerRegistry.put(this);
86     }
87 
getLogger()88     public Logger getLogger() {
89         return logger;
90     }
91 
setLogger(Logger logger)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      */
start(String name)100     public void start(String name) {
101         stopLastTimeInstrument();
102         StopWatch childSW = new StopWatch(name);
103         childTimeInstrumentList.add(childSW);
104     }
105 
startNested(String name)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 
getLastTimeInstrument()115     TimeInstrument getLastTimeInstrument() {
116         if (childTimeInstrumentList.size() > 0) {
117             return childTimeInstrumentList.get(childTimeInstrumentList.size() - 1);
118         } else {
119             return null;
120         }
121     }
122 
stopLastTimeInstrument()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 
elapsedTime()137     public long elapsedTime() {
138         return globalStopWatch.elapsedTime();
139     }
140 
stop()141     public TimeInstrument stop() {
142         stopLastTimeInstrument();
143         globalStopWatch.stop();
144         return this;
145     }
146 
getStatus()147     public TimeInstrumentStatus getStatus() {
148         return globalStopWatch.status;
149     }
150 
151     /**
152      * This method is used in tests.
153      */
sanityCheck()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 
print()183     public void print() {
184         System.out.println(toString());
185     }
186 
187     @Override
toString()188     public String toString() {
189         DurationUnit du = Util.selectDurationUnitForDisplay(globalStopWatch);
190         return buildProfilerString(du, TOP_PROFILER_FIRST_PREFIX, TOTAL_ELAPSED, "");
191     }
192 
log()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      */
getCopyOfChildTimeInstruments()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      */
getCopyOfGlobalStopWatch()222     public StopWatch getCopyOfGlobalStopWatch() {
223         StopWatch copy = new StopWatch(globalStopWatch);
224         return copy;
225     }
226 
buildProfilerString(DurationUnit du, String firstPrefix, String label, String indentation)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 
buildStopWatchString(StringBuilder buf, DurationUnit du, String prefix, String indentation, StopWatch sw)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