Save This Page
1 /*
2 * Copyright (c) 2002-2003, Atlassian Software Systems Pty Ltd All rights reserved.
3 *
4 * Redistribution and use in source and binary forms, with or without modification,
5 * are permitted provided that the following conditions are met:
6 *
7 * * Redistributions of source code must retain the above copyright notice,
8 * this list of conditions and the following disclaimer.
9 * * Redistributions in binary form must reproduce the above copyright notice,
10 * this list of conditions and the following disclaimer in the documentation and/or
11 * other materials provided with the distribution.
12 * * Neither the name of Atlassian Software Systems Pty Ltd nor the names of
13 * its contributors may be used to endorse or promote products derived from this
14 * software without specific prior written permission.
15 *
16 * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS IS" AND
17 * ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED
18 * WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE ARE
19 * DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT OWNER OR CONTRIBUTORS BE LIABLE FOR
20 * ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES
21 * (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES;
22 * LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON
23 * ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
24 * (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF THIS
25 * SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
26 */
27 package com.opensymphony.xwork2.util.profiling;
28
29 import com.opensymphony.xwork2.util.logging.Logger;
30 import com.opensymphony.xwork2.util.logging.LoggerFactory;
31
32
33 /**
34 * A timer stack.
35 *
36 * <p />
37 *
38 * <!-- START SNIPPET: profilingAspect_struts2 -->
39 *
40 * Struts2 profiling aspects involves the following :-
41 * <ul>
42 * <li>ActionContextCleanUp</li>
43 * <li>FreemarkerPageFilter</li>
44 * <li>DispatcherFilter</li>
45 * <ul>
46 * <li>Dispatcher</li>
47 * <ul>
48 * <li>creation of DefaultActionProxy</li>
49 * <ul>
50 * <li>creation of DefaultActionInvocation</li>
51 * <ul>
52 * <li>creation of Action</li>
53 * </ul>
54 * </ul>
55 * <li>execution of DefaultActionProxy</li>
56 * <ul>
57 * <li>invocation of DefaultActionInvocation</li>
58 * <ul>
59 * <li>invocation of Interceptors</li>
60 * <li>invocation of Action</li>
61 * <li>invocation of PreResultListener</li>
62 * <li>invocation of Result</li>
63 * </ul>
64 * </ul>
65 * </ul>
66 * </ul>
67 * </ul>
68 *
69 * <!-- END SNIPPET: profilingAspect_struts2 -->
70 *
71 *
72 * <!-- START SNIPPET: profilingAspect_xwork -->
73 *
74 * XWork2 profiling aspects involves the following :-
75 * <ul>
76 * <ul>
77 * <li>creation of DefaultActionProxy</li>
78 * <ul>
79 * <li>creation of DefaultActionInvocation</li>
80 * <ul>
81 * <li>creation of Action</li>
82 * </ul>
83 * </ul>
84 * <li>execution of DefaultActionProxy</li>
85 * <ul>
86 * <li>invocation of DefaultActionInvocation</li>
87 * <ul>
88 * <li>invocation of Interceptors</li>
89 * <li>invocation of Action</li>
90 * <li>invocation of PreResultListener</li>
91 * <li>invocation of Result</li>
92 * </ul>
93 * </ul>
94 * </ul>
95 * </ul>
96 *
97 * <!-- END SNIPPET: profilingAspect_xwork -->
98 *
99 *
100 * <!-- START SNIPPET: activationDescription -->
101 *
102 * Activating / Deactivating of the profiling feature could be done through:-
103 *
104 * <!-- END SNIPPET: activationDescription -->
105 *
106 * <p/>
107 *
108 * System properties:- <p/>
109 * <pre>
110 * <!-- START SNIPPET: activationThroughSystemProperty -->
111 *
112 * -Dxwork.profile.activate=true
113 *
114 * <!-- END SNIPPET: activationThroughSystemProperty -->
115 * </pre>
116 *
117 * <!-- START SNIPPET: activationThroughSystemPropertyDescription -->
118 *
119 * This could be done in the container startup script eg. CATALINA_OPTS in catalina.sh
120 * (tomcat) or using "java -Dxwork.profile.activate=true -jar start.jar" (jetty)
121 *
122 * <!-- END SNIPPET: activationThroughSystemPropertyDescription -->
123 *
124 * <p/>
125 * Code :- <p/>
126 * <pre>
127 * <!-- START SNIPPET: activationThroughCode -->
128 *
129 * UtilTimerStack.setActivate(true);
130 *
131 * // or
132 *
133 * System.setProperty("xwork.profile.activate", "true");
134 *
135 * // or
136 *
137 * System.setProperty(UtilTimerStack.ACTIVATE_PROPERTY, "true");
138 *
139 * <!-- END SNIPPET: activationThroughCode -->
140 * </pre>
141 *
142 *
143 *
144 * <!-- START SNIPPET: activationThroughCodeDescription -->
145 *
146 * This could be done in a static block, in a Spring bean with lazy-init="false",
147 * in a Servlet with init-on-startup as some numeric value, in a Filter or
148 * Listener's init method etc.
149 *
150 * <!-- END SNIPPET: activationThroughCodeDescription -->
151 *
152 * <p/>
153 * Parameter:-
154 *
155 * <pre>
156 * <!-- START SNIPPET: activationThroughParameter -->
157 *
158 * <action ... >
159 * ...
160 * <interceptor-ref name="profiling">
161 * <param name="profilingKey">profiling</param>
162 * </interceptor-ref>
163 * ...
164 * </action>
165 *
166 * or
167 *
168 * <action .... >
169 * ...
170 * <interceptor-ref name="profiling" />
171 * ...
172 * </action>
173 *
174 * through url
175 *
176 * http://host:port/context/namespace/someAction.action?profiling=true
177 *
178 * through code
179 *
180 * ActionContext.getContext().getParameters().put("profiling", "true);
181 *
182 * <!-- END SNIPPET: activationThroughParameter -->
183 * </pre>
184 *
185 *
186 * <!-- START SNIPPET: activationThroughParameterDescription -->
187 *
188 * To use profiling activation through parameter, one will need to pass in through
189 * the 'profiling' parameter (which is the default) and could be changed through
190 * the param tag in the interceptor-ref.
191 *
192 * <!-- END SNIPPET: activationThroughParameterDescription -->
193 *
194 * <p/>
195 * Warning:<p/>
196 * <!-- START SNIPPET: activationThroughParameterWarning -->
197 *
198 * Profiling activation through a parameter requires the following:
199 *
200 * <ul>
201 * <li>Profiling interceptor in interceptor stack</li>
202 * <li>dev mode on (struts.devMode=true in struts.properties)
203 * </ul>
204 *
205 * <!-- END SNIPPET: activationThroughParameterWarning -->
206 *
207 * <p/>
208 *
209 * <!-- START SNIPPET: filteringDescription -->
210 *
211 * One could filter out the profile logging by having a System property as follows. With this
212 * 'xwork.profile.mintime' property, one could only log profile information when its execution time
213 * exceed those specified in 'xwork.profile.mintime' system property. If no such property is specified,
214 * it will be assumed to be 0, hence all profile information will be logged.
215 *
216 * <!-- END SNIPPET: filteringDescription -->
217 *
218 * <pre>
219 * <!-- START SNIPPET: filteringCode -->
220 *
221 * -Dxwork.profile.mintime=10000
222 *
223 * <!-- END SNIPPET: filteringCode -->
224 * </pre>
225 *
226 * <!-- START SNIPPET: methodDescription -->
227 *
228 * One could extend the profiling feature provided by Struts2 in their web application as well.
229 *
230 * <!-- END SNIPPET: methodDescription -->
231 *
232 * <pre>
233 * <!-- START SNIPPET: method1 -->
234 *
235 * String logMessage = "Log message";
236 * UtilTimerStack.push(logMessage);
237 * try {
238 * // do some code
239 * }
240 * finally {
241 * UtilTimerStack.pop(logMessage); // this needs to be the same text as above
242 * }
243 *
244 * <!-- END SNIPPET: method1 -->
245 * </pre>
246 *
247 * or
248 *
249 * <pre>
250 * <!-- START SNIPPET: method2 -->
251 *
252 * String result = UtilTimerStack.profile("purchaseItem: ",
253 * new UtilTimerStack.ProfilingBlock<String>() {
254 * public String doProfiling() {
255 * // do some code
256 * return "Ok";
257 * }
258 * });
259 *
260 * <!-- END SNIPPET: method2 -->
261 * </pre>
262 *
263 *
264 * <!-- START SNIPPET: profileLogFile -->
265 *
266 * Profiled result is logged using commons-logging under the logger named
267 * 'com.opensymphony.xwork2.util.profiling.UtilTimerStack'. Depending on the underlying logging implementation
268 * say if it is Log4j, one could direct the log to appear in a different file, being emailed to someone or have
269 * it stored in the db.
270 *
271 * <!-- END SNIPPET: profileLogFile -->
272 *
273 * @version $Date$ $Id$
274 */
275 public class UtilTimerStack
276 {
277
278 // A reference to the current ProfilingTimerBean
279 protected static ThreadLocal<ProfilingTimerBean> current = new ThreadLocal<ProfilingTimerBean>();
280
281 /**
282 * System property that controls whether this timer should be used or not. Set to "true" activates
283 * the timer. Set to "false" to disactivate.
284 */
285 public static final String ACTIVATE_PROPERTY = "xwork.profile.activate";
286
287 /**
288 * System property that controls the min time, that if exceeded will cause a log (at INFO level) to be
289 * created.
290 */
291 public static final String MIN_TIME = "xwork.profile.mintime";
292
293 private static final Logger LOG = LoggerFactory.getLogger(UtilTimerStack.class);
294
295 /**
296 * Create and start a performance profiling with the <code>name</code> given. Deal with
297 * profile hierarchy automatically, so caller don't have to be concern about it.
298 *
299 * @param name profile name
300 */
301 public static void push(String name)
302 {
303 if (!isActive())
304 return;
305
306 //create a new timer and start it
307 ProfilingTimerBean newTimer = new ProfilingTimerBean(name);
308 newTimer.setStartTime();
309
310 //if there is a current timer - add the new timer as a child of it
311 ProfilingTimerBean currentTimer = (ProfilingTimerBean) current.get();
312 if (currentTimer != null)
313 {
314 currentTimer.addChild(newTimer);
315 }
316
317 //set the new timer to be the current timer
318 current.set(newTimer);
319 }
320
321 /**
322 * End a preformance profiling with the <code>name</code> given. Deal with
323 * profile hierarchy automatically, so caller don't have to be concern about it.
324 *
325 * @param name profile name
326 */
327 public static void pop(String name)
328 {
329 if (!isActive())
330 return;
331
332 ProfilingTimerBean currentTimer = (ProfilingTimerBean) current.get();
333
334 //if the timers are matched up with each other (ie push("a"); pop("a"));
335 if (currentTimer != null && name != null && name.equals(currentTimer.getResource()))
336 {
337 currentTimer.setEndTime();
338 ProfilingTimerBean parent = currentTimer.getParent();
339 //if we are the root timer, then print out the times
340 if (parent == null)
341 {
342 printTimes(currentTimer);
343 current.set(null); //for those servers that use thread pooling
344 }
345 else
346 {
347 current.set(parent);
348 }
349 }
350 else
351 {
352 //if timers are not matched up, then print what we have, and then print warning.
353 if (currentTimer != null)
354 {
355 printTimes(currentTimer);
356 current.set(null); //prevent printing multiple times
357 LOG.warn("Unmatched Timer. Was expecting " + currentTimer.getResource() + ", instead got " + name);
358 }
359 }
360
361
362 }
363
364 /**
365 * Do a log (at INFO level) of the time taken for this particular profiling.
366 *
367 * @param currentTimer profiling timer bean
368 */
369 private static void printTimes(ProfilingTimerBean currentTimer)
370 {
371 LOG.info(currentTimer.getPrintable(getMinTime()));
372 }
373
374 /**
375 * Get the min time for this profiling, it searches for a System property
376 * 'xwork.profile.mintime' and default to 0.
377 *
378 * @return long
379 */
380 private static long getMinTime()
381 {
382 try
383 {
384 return Long.parseLong(System.getProperty(MIN_TIME, "0"));
385 }
386 catch (NumberFormatException e)
387 {
388 return -1;
389 }
390 }
391
392 /**
393 * Determine if profiling is being activated, by searching for a system property
394 * 'xwork.profile.activate', default to false (profiling is off).
395 *
396 * @return <tt>true</tt>, if active, <tt>false</tt> otherwise.
397 */
398 public static boolean isActive()
399 {
400 return System.getProperty(ACTIVATE_PROPERTY) != null;
401 }
402
403 /**
404 * Turn profiling on or off.
405 *
406 * @param active
407 */
408 public static void setActive(boolean active)
409 {
410 if (active)
411 System.setProperty(ACTIVATE_PROPERTY, "true");
412 else
413 System.clearProperty(ACTIVATE_PROPERTY);
414 }
415
416
417 /**
418 * A convenience method that allows <code>block</code> of code subjected to profiling to be executed
419 * and avoid the need of coding boiler code that does pushing (UtilTimeBean.push(...)) and
420 * poping (UtilTimerBean.pop(...)) in a try ... finally ... block.
421 *
422 * <p/>
423 *
424 * Example of usage:
425 * <pre>
426 * // we need a returning result
427 * String result = UtilTimerStack.profile("purchaseItem: ",
428 * new UtilTimerStack.ProfilingBlock<String>() {
429 * public String doProfiling() {
430 * getMyService().purchaseItem(....)
431 * return "Ok";
432 * }
433 * });
434 * </pre>
435 * or
436 * <pre>
437 * // we don't need a returning result
438 * UtilTimerStack.profile("purchaseItem: ",
439 * new UtilTimerStack.ProfilingBlock<String>() {
440 * public String doProfiling() {
441 * getMyService().purchaseItem(....)
442 * return null;
443 * }
444 * });
445 * </pre>
446 *
447 * @param <T> any return value if there's one.
448 * @param name profile name
449 * @param block code block subjected to profiling
450 * @return T
451 * @throws Exception
452 */
453 public static <T> T profile(String name, ProfilingBlock<T> block) throws Exception {
454 UtilTimerStack.push(name);
455 try {
456 return block.doProfiling();
457 }
458 finally {
459 UtilTimerStack.pop(name);
460 }
461 }
462
463 /**
464 * A callback interface where code subjected to profile is to be executed. This eliminates the need
465 * of coding boiler code that does pushing (UtilTimerBean.push(...)) and poping (UtilTimerBean.pop(...))
466 * in a try ... finally ... block.
467 *
468 * @version $Date$ $Id$
469 *
470 * @param <T>
471 */
472 public static interface ProfilingBlock<T> {
473
474 /**
475 * Method that execute the code subjected to profiling.
476 *
477 * @return profiles Type
478 * @throws Exception
479 */
480 T doProfiling() throws Exception;
481 }
482 }