1 /* Copyright (c) 2008-2009 HomeAway, Inc.
2 * All rights reserved. http://www.perf4j.org
3 *
4 * Licensed under the Apache License, Version 2.0 (the "License");
5 * you may not use this file except in compliance with the License.
6 * You may obtain a copy of the License at
7 *
8 * http://www.apache.org/licenses/LICENSE-2.0
9 *
10 * Unless required by applicable law or agreed to in writing, software
11 * distributed under the License is distributed on an "AS IS" BASIS,
12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13 * See the License for the specific language governing permissions and
14 * limitations under the License.
15 */
16 package org.perf4j;
17
18 /**
19 * A LoggingStopWatch prevents the need to explicitly send the StopWatch string to a Logger when stopping. Instead,
20 * all of the stop() and lap() methods themselves are responsible for persisting the StopWatch:
21 * <pre>
22 * LoggingStopWatch stopWatch = new LoggingStopWatch();
23 * ...some code
24 * stopWatch.stop("codeBlock1"); //calling stop writes the StopWatch string to std err.
25 * </pre>
26 * This class just writes all StopWatch messages to the standard error stream, but subclasses will use Loggers from
27 * various logging frameworks to persist the StopWatch.
28 *
29 * @author Alex Devine
30 */
31 @SuppressWarnings("serial")
32 public class LoggingStopWatch extends StopWatch {
33 /**
34 * This threshold determines if a log call will be made. Only elapsed times greater than this amount will be logged.
35 */
36 private long timeThreshold = 0L;
37
38 /**
39 * Set this to true if both normal and slow suffixes should be appended to every StopWatch tag.
40 */
41 private boolean normalAndSlowSuffixesEnabled = false;
42
43 /**
44 * If normalAndSlowSuffixesEnabled == true then this suffix will be appended to the tag for elapsedTimes < timeThreshold.
45 * If normalAndSlowSuffixesEnabled == true and timeThreshold == 0 then this suffix will ALWAYS be appended to the tag.
46 */
47 private String normalSuffix = ".normal";
48
49 /**
50 * If normalAndSlowSuffixesEnabled == true then this suffix will be appended to the tag for elapsedTimes >= timeThreshold.
51 * If normalAndSlowSuffixesEnabled == true and timeThreshold == 0 then this suffix will NEVER be appended to the tag.
52 */
53 private String slowSuffix = ".slow";
54
55 // --- Constructors ---
56
57 /**
58 * Creates a LoggingStopWatch with a blank tag, no message and started at the instant of creation.
59 */
60 public LoggingStopWatch() {
61 super();
62 }
63
64 /**
65 * Creates a LoggingStopWatch with the specified tag, no message and started at the instant of creation.
66 *
67 * @param tag The tag name for this timing call. Tags are used to group timing logs, thus each block of code being
68 * timed should have a unique tag. Note that tags can take a hierarchical format using dot notation.
69 */
70 public LoggingStopWatch(String tag) {
71 super(tag);
72 }
73
74 /**
75 * Creates a LoggingStopWatch with the specified tag and message, started an the instant of creation.
76 *
77 * @param tag The tag name for this timing call. Tags are used to group timing logs, thus each block of code
78 * being timed should have a unique tag. Note that tags can take a hierarchical format using dot
79 * notation.
80 * @param message Additional text to be printed with the logging statement of this LoggingStopWatch.
81 */
82 public LoggingStopWatch(String tag, String message) {
83 super(tag, message);
84 }
85
86 /**
87 * Creates a LoggingStopWatch with a specified start and elapsed time, tag, and message. This constructor should
88 * normally not be called by third party code; it is intended to allow for deserialization of StopWatch logs.
89 *
90 * @param startTime The start time in milliseconds
91 * @param elapsedTime The elapsed time in milliseconds
92 * @param tag The tag used to group timing logs of the same code block
93 * @param message Additional message text
94 */
95 public LoggingStopWatch(long startTime, long elapsedTime, String tag, String message) {
96 super(startTime, elapsedTime, tag, message);
97 }
98
99 // --- Bean Properties ---
100 /**
101 * Gets a threshold level, in milliseconds, below which logging calls will not be made. Defaults to 0, meaning that
102 * the log method is always called on stop or lap regardless of the elapsed time.
103 *
104 * @return The time threshold in milliseconds.
105 */
106 public long getTimeThreshold() {
107 return timeThreshold;
108 }
109
110 /**
111 * Sets a threshold level, in milliseconds, below which logging calls will not be made. You can set this to a
112 * high positive value if you only want logging to occur for abnormally slow execution times. Note, though, that
113 * you may wish to leave the threshold at 0 and attach a
114 * {@link org.perf4j.log4j.JmxAttributeStatisticsAppender} in the logging configuration to be notified when
115 * times are outside acceptable thresholds.
116 *
117 * @param timeThreshold The minimum elapsed time, in milliseconds, below which log calls will not be made.
118 * @return this instance, for use with method chaining if desired
119 * @see org.perf4j.log4j.JmxAttributeStatisticsAppender#getNotificationThresholds()
120 */
121 public LoggingStopWatch setTimeThreshold(long timeThreshold) {
122 this.timeThreshold = timeThreshold;
123 return this;
124 }
125
126 /**
127 * Determines whether or not to append normalSuffix or slowSuffix to every tag logged by this stopwatch.
128 * @return whether or not to append normalSuffix or slowSuffix to every tag logged by this stopwatch.
129 */
130 public boolean isNormalAndSlowSuffixesEnabled() {
131 return normalAndSlowSuffixesEnabled;
132 }
133
134 /**
135 * Sets whether to append normalSuffix and slowSuffix when timeThreshold > 0 AND elapsedTime >= timeThreshold
136 * @param normalAndSlowSuffixesEnabled true enables logging extra suffixes to normal and slow events; false (default) suppresses the suffixes
137 */
138 public LoggingStopWatch setNormalAndSlowSuffixesEnabled(boolean normalAndSlowSuffixesEnabled) {
139 this.normalAndSlowSuffixesEnabled = normalAndSlowSuffixesEnabled;
140 return this;
141 }
142
143 /**
144 * The suffix to append to the tag if normalAndSlowSuffixesEnabled=true and elapsedTime < timeThreshold and timeThreshold > 0.
145 * Default is ".normal".
146 * @return the suffix to append if normalAndSlowSuffixesEnabled=true and the event was normal and under the threshold
147 */
148 public String getNormalSuffix() {
149 return normalSuffix;
150 }
151
152 /**
153 * Sets the suffix to use when normalAndSlowSuffixesEnabled=true and timeThreshold > 0 and elapsedTime < timeThreshold.
154 * Setting this to "" is equivalent to setting to null.
155 * @param normalSuffix the suffix to append if normalAndSlowSuffixesEnabled and the elapsedtime is under the threshold
156 */
157 public LoggingStopWatch setNormalSuffix(String normalSuffix) {
158 if (normalSuffix == null || "".equals(normalSuffix)) {
159 throw new IllegalArgumentException("normalSuffix cannot be blank. param=" + normalSuffix);
160 }
161 this.normalSuffix = normalSuffix;
162 return this;
163 }
164
165 /**
166 * The suffix to append to the tag if normalAndSlowSuffixesEnabled=true and elapsedTime >= timeThreshold and timeThreshold > 0.
167 * Default is ".slow"
168 * @return the suffix to append if normalAndSlowSuffixesEnabled=true and the event was slow and over the threshold.
169 */
170 public String getSlowSuffix() {
171 return slowSuffix;
172 }
173
174 /**
175 * Sets the suffix to use when normalAndSlowSuffixesEnabled=true and timeThreshold > 0 and elapsedTime >= timeThreshold.
176 * Setting this to "" is equivalent to setting to null.
177 * @param slowSuffix the suffix to append if normalAndSlowSuffixesEnabled and the elapsedtime is under the threshold
178 */
179 public LoggingStopWatch setSlowSuffix(String slowSuffix) {
180 if (slowSuffix == null || "".equals(slowSuffix)) {
181 throw new IllegalArgumentException("slowSuffix cannot be blank. param=" + slowSuffix);
182 }
183 this.slowSuffix = slowSuffix;
184 return this;
185 }
186
187 /*
188 * If normalAndSlowSuffixesEnabled AND timeThreshold >0 AND elapsedTime >= timeThreshold
189 * then append slow suffix.<br/>
190 * If normalAndSlowSuffixesEnabled AND (timeThreshold <=0 OR elapsedTime < timeThreshold)
191 * then append normal suffix.<br/>
192 * Otherwise, use the superclass's tag.
193 */
194 public String getTag() {
195 long timeThreshold = getTimeThreshold(); // so that child classes can override
196 return isNormalAndSlowSuffixesEnabled() ?
197 super.getTag() + (getElapsedTime() >= timeThreshold ? getSlowSuffix() : getNormalSuffix()) :
198 super.getTag();
199 }
200
201 // Just overridden to make use of covariant return types
202 public LoggingStopWatch setTag(String tag) {
203 super.setTag(tag);
204 return this;
205 }
206
207 // Just overridden to make use of covariant return types
208 public LoggingStopWatch setMessage(String message) {
209 super.setMessage(message);
210 return this;
211 }
212
213 // --- Stop/Lap/Helper Methods ---
214 /**
215 * This stop method is overridden to perform the logging itself instead of needing to make a separate call to
216 * persist the timing information.
217 *
218 * @return this.toString(), however, this should not be passed to a logger as it will have already been logged.
219 */
220 public String stop() {
221 String retVal = super.stop();
222 doLogInternal(retVal, null);
223 return retVal;
224 }
225
226 /**
227 * In cases where a code block terminated by throwing an exception, you may wish to have the exception logged in
228 * addition to the time it took to execute the block, in which case this method will write out the exception's
229 * stack trace in addition to the StopWatch timing method.
230 *
231 * @param exception The exception that was thrown by the timed code block
232 * @return this.toString(), however, this should not be passed to a logger as it will have already been logged.
233 */
234 public String stop(Throwable exception) {
235 String retVal = super.stop();
236 doLogInternal(retVal, exception);
237 return retVal;
238 }
239
240 /**
241 * Identical to {@link #stop(String)}, but also allows you to specify an exception to be logged.
242 *
243 * @param tag The grouping tag for this StopWatch
244 * @param exception The exception that was thrown by the timed code block
245 * @return this.toString(), however, this should not be passed to a logger as it will have already been logged.
246 */
247 public String stop(String tag, Throwable exception) {
248 setTag(tag);
249 return stop(exception);
250 }
251
252 /**
253 * Identical to {@link #stop(String, String)}, but also allows you to specify an exception to be logged.
254 *
255 * @param tag The grouping tag for this StopWatch
256 * @param message A descriptive message about the timed block
257 * @param exception The exception that was thrown by the timed code block
258 * @return this.toString(), however, this should not be passed to a logger as it will have already been logged.
259 */
260 public String stop(String tag, String message, Throwable exception) {
261 setTag(tag);
262 setMessage(message);
263 return stop(exception);
264 }
265
266 /**
267 * Identical to {@link #lap(String)}, but also allows you to specify an exception to be logged.
268 *
269 * @param tag The grouping tag for the PREVIOUS code block that was timed.
270 * @param exception The exception that was thrown by the timed code block.
271 * @return this.toString(), however, this should not be passed to a logger as it will have already been logged.
272 */
273 public String lap(String tag, Throwable exception) {
274 String retVal = stop(tag, exception);
275 start();
276 return retVal;
277 }
278
279 /**
280 * Identical to {@link #lap(String, String)}, but also allows you to specify an exception to be logged.
281 *
282 * @param tag The grouping tag for the PREVIOUS code block that was timed.
283 * @param message A descriptive message about the timed block
284 * @param exception The exception that was thrown by the timed code block
285 * @return this.toString(), however, this should not be passed to a logger as it will have already been logged.
286 */
287 public String lap(String tag, String message, Throwable exception) {
288 String retVal = stop(tag, message, exception);
289 start();
290 return retVal;
291 }
292
293 /**
294 * Determines whether or not logging is currently enabled for normal log messages for this StopWatch. This
295 * implementation always returns true, but subclasses should override this method if logging can be disabled. For
296 * example, a StopWatch that uses log4j Loggers will return false if the Logger is not currently enabled for the
297 * Level at which the log method is called.
298 *
299 * @return true if calls to one of the stop() or lap() methods that do NOT take an exception will result in the
300 * StopWatch being written to a persisting log.
301 */
302 public boolean isLogging() { return true; }
303
304 // --- Template Methods ---
305 /**
306 * This log method can be overridden by subclasses in order to persist the StopWatch, for example by using a
307 * log4j Logger. The default implementation here just writes the StopWatch to the standard error stream.
308 *
309 * @param stopWatchAsString The serialized StopWatch string
310 * @param exception An exception, if any, that was also passed to the stop() or lap() methods - may be null.
311 */
312 protected void log(String stopWatchAsString, Throwable exception) {
313 System.err.println(stopWatchAsString);
314 if (exception != null) {
315 exception.printStackTrace();
316 }
317 }
318
319 // --- Object Methods ---
320
321 public LoggingStopWatch clone() {
322 return (LoggingStopWatch) super.clone();
323 }
324
325 // --- Private Methods ---
326 // Helper method only calls log if elapsed time is greater than the time threshold
327 private void doLogInternal(String stopWatchAsString, Throwable exception) {
328 //if normalAndSlowSuffixesEnabled then always log with the suffixes added
329 //getTag() should take care of appending the correct tag, and should already be part of stopWatchAsString
330 //Otherwise we default to the backward-compatible behavior: namely:
331 //in most cases timeThreshold will be 0, so just short circuit out as fast as possible
332 long elapsedTime = getElapsedTime(); // to allow for subclasses to override this value
333 long timeThreshold = getTimeThreshold(); // to allow for subclasses to override this value
334 if (timeThreshold == 0 || isNormalAndSlowSuffixesEnabled() || elapsedTime >= timeThreshold) {
335 log(stopWatchAsString, exception);
336 }
337 }
338 }