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 * <!-- END SNIPPET: activationThroughCode -->
132 * </pre>
133 *
134 *
135 *
136 * <!-- START SNIPPET: activationThroughCodeDescription -->
137 *
138 * This could be done in a static block, in a Spring bean with lazy-init="false",
139 * in a Servlet with init-on-startup as some numeric value, in a Filter or
140 * Listener's init method etc.
141 *
142 * <!-- END SNIPPET: activationThroughCodeDescription -->
143 *
144 * <p/>
145 * Parameter:-
146 *
147 * <pre>
148 * <!-- START SNIPPET: activationThroughParameter -->
149 *
150 * <action ... >
151 * ...
152 * <interceptor-ref name="profiling">
153 * <param name="profilingKey">profiling</param>
154 * </interceptor-ref>
155 * ...
156 * </action>
157 *
158 * or
159 *
160 * <action .... >
161 * ...
162 * <interceptor-ref name="profiling" />
163 * ...
164 * </action>
165 *
166 * through url
167 *
168 * http://host:port/context/namespace/someAction.action?profiling=true
169 *
170 * through code
171 *
172 * ActionContext.getContext().getParameters().put("profiling", "true);
173 *
174 * <!-- END SNIPPET: activationThroughParameter -->
175 * </pre>
176 *
177 *
178 * <!-- START SNIPPET: activationThroughParameterDescription -->
179 *
180 * To use profiling activation through parameter, one will need to pass in through
181 * the 'profiling' parameter (which is the default) and could be changed through
182 * the param tag in the interceptor-ref.
183 *
184 * <!-- END SNIPPET: activationThroughParameterDescription -->
185 *
186 * <p/>
187 * Warning:<p/>
188 * <!-- START SNIPPET: activationThroughParameterWarning -->
189 *
190 * Profiling activation through a parameter requires the following:
191 *
192 * <ul>
193 * <li>Profiling interceptor in interceptor stack</li>
194 * <li>dev mode on (struts.devMode=true in struts.properties)
195 * </ul>
196 *
197 * <!-- END SNIPPET: activationThroughParameterWarning -->
198 *
199 * <p/>
200 *
201 * <!-- START SNIPPET: filteringDescription -->
202 *
203 * One could filter out the profile logging by having a System property as follows. With this
204 * 'xwork.profile.mintime' property, one could only log profile information when its execution time
205 * exceed those specified in 'xwork.profile.mintime' system property. If no such property is specified,
206 * it will be assumed to be 0, hence all profile information will be logged.
207 *
208 * <!-- END SNIPPET: filteringDescription -->
209 *
210 * <pre>
211 * <!-- START SNIPPET: filteringCode -->
212 *
213 * -Dxwork.profile.mintime=10000
214 *
215 * <!-- END SNIPPET: filteringCode -->
216 * </pre>
217 *
218 * <!-- START SNIPPET: methodDescription -->
219 *
220 * One could extend the profiling feature provided by Struts2 in their web application as well.
221 *
222 * <!-- END SNIPPET: methodDescription -->
223 *
224 * <pre>
225 * <!-- START SNIPPET: method1 -->
226 *
227 * String logMessage = "Log message";
228 * UtilTimerStack.push(logMessage);
229 * try {
230 * // do some code
231 * }
232 * finally {
233 * UtilTimerStack.pop(logMessage); // this needs to be the same text as above
234 * }
235 *
236 * <!-- END SNIPPET: method1 -->
237 * </pre>
238 *
239 * or
240 *
241 * <pre>
242 * <!-- START SNIPPET: method2 -->
243 *
244 * String result = UtilTimerStack.profile("purchaseItem: ",
245 * new UtilTimerStack.ProfilingBlock<String>() {
246 * public String doProfiling() {
247 * // do some code
248 * return "Ok";
249 * }
250 * });
251 *
252 * <!-- END SNIPPET: method2 -->
253 * </pre>
254 *
255 *
256 * <!-- START SNIPPET: profileLogFile -->
257 *
258 * Profiled result is logged using commons-logging under the logger named
259 * 'com.opensymphony.xwork2.util.profiling.UtilTimerStack'. Depending on the underlying logging implementation
260 * say if it is Log4j, one could direct the log to appear in a different file, being emailed to someone or have
261 * it stored in the db.
262 *
263 * <!-- END SNIPPET: profileLogFile -->
264 *
265 * @version $Date$ $Id$
266 */
267 public class UtilTimerStack
268 {
269
270 // A reference to the current ProfilingTimerBean
271 protected static ThreadLocal<ProfilingTimerBean> current = new ThreadLocal<ProfilingTimerBean>();
272
273 /**
274 * System property that controls whether this timer should be used or not. Set to "true" activates
275 * the timer. Set to "false" to disactivate.
276 */
277 public static final String ACTIVATE_PROPERTY = "xwork.profile.activate";
278
279 /**
280 * System property that controls the min time, that if exceeded will cause a log (at INFO level) to be
281 * created.
282 */
283 public static final String MIN_TIME = "xwork.profile.mintime";
284
285 private static final Logger LOG = LoggerFactory.getLogger(UtilTimerStack.class);
286
287 /**
288 * Initialized in a static block, it can be changed at runtime by calling setActive(...)
289 */
290 private static boolean active;
291
292 static {
293 active = "true".equalsIgnoreCase(System.getProperty(ACTIVATE_PROPERTY));
294 }
295
296 /**
297 * Create and start a performance profiling with the <code>name</code> given. Deal with
298 * profile hierarchy automatically, so caller don't have to be concern about it.
299 *
300 * @param name profile name
301 */
302 public static void push(String name)
303 {
304 if (!isActive())
305 return;
306
307 //create a new timer and start it
308 ProfilingTimerBean newTimer = new ProfilingTimerBean(name);
309 newTimer.setStartTime();
310
311 //if there is a current timer - add the new timer as a child of it
312 ProfilingTimerBean currentTimer = (ProfilingTimerBean) current.get();
313 if (currentTimer != null)
314 {
315 currentTimer.addChild(newTimer);
316 }
317
318 //set the new timer to be the current timer
319 current.set(newTimer);
320 }
321
322 /**
323 * End a preformance profiling with the <code>name</code> given. Deal with
324 * profile hierarchy automatically, so caller don't have to be concern about it.
325 *
326 * @param name profile name
327 */
328 public static void pop(String name)
329 {
330 if (!isActive())
331 return;
332
333 ProfilingTimerBean currentTimer = (ProfilingTimerBean) current.get();
334
335 //if the timers are matched up with each other (ie push("a"); pop("a"));
336 if (currentTimer != null && name != null && name.equals(currentTimer.getResource()))
337 {
338 currentTimer.setEndTime();
339 ProfilingTimerBean parent = currentTimer.getParent();
340 //if we are the root timer, then print out the times
341 if (parent == null)
342 {
343 printTimes(currentTimer);
344 current.set(null); //for those servers that use thread pooling
345 }
346 else
347 {
348 current.set(parent);
349 }
350 }
351 else
352 {
353 //if timers are not matched up, then print what we have, and then print warning.
354 if (currentTimer != null)
355 {
356 printTimes(currentTimer);
357 current.set(null); //prevent printing multiple times
358 LOG.warn("Unmatched Timer. Was expecting " + currentTimer.getResource() + ", instead got " + name);
359 }
360 }
361
362
363 }
364
365 /**
366 * Do a log (at INFO level) of the time taken for this particular profiling.
367 *
368 * @param currentTimer profiling timer bean
369 */
370 private static void printTimes(ProfilingTimerBean currentTimer)
371 {
372 LOG.info(currentTimer.getPrintable(getMinTime()));
373 }
374
375 /**
376 * Get the min time for this profiling, it searches for a System property
377 * 'xwork.profile.mintime' and default to 0.
378 *
379 * @return long
380 */
381 private static long getMinTime()
382 {
383 try
384 {
385 return Long.parseLong(System.getProperty(MIN_TIME, "0"));
386 }
387 catch (NumberFormatException e)
388 {
389 return -1;
390 }
391 }
392
393 /**
394 * Determine if profiling is being activated, by searching for a system property
395 * 'xwork.profile.activate', default to false (profiling is off).
396 *
397 * @return <tt>true</tt>, if active, <tt>false</tt> otherwise.
398 */
399 public static boolean isActive()
400 {
401 return active;
402 }
403
404 /**
405 * Turn profiling on or off.
406 *
407 * @param active
408 */
409 public static void setActive(boolean active)
410 {
411 if (active)
412 System.setProperty(ACTIVATE_PROPERTY, "true");
413 else
414 System.clearProperty(ACTIVATE_PROPERTY);
415
416 UtilTimerStack.active = active;
417 }
418
419
420 /**
421 * A convenience method that allows <code>block</code> of code subjected to profiling to be executed
422 * and avoid the need of coding boiler code that does pushing (UtilTimeBean.push(...)) and
423 * poping (UtilTimerBean.pop(...)) in a try ... finally ... block.
424 *
425 * <p/>
426 *
427 * Example of usage:
428 * <pre>
429 * // we need a returning result
430 * String result = UtilTimerStack.profile("purchaseItem: ",
431 * new UtilTimerStack.ProfilingBlock<String>() {
432 * public String doProfiling() {
433 * getMyService().purchaseItem(....)
434 * return "Ok";
435 * }
436 * });
437 * </pre>
438 * or
439 * <pre>
440 * // we don't need a returning result
441 * UtilTimerStack.profile("purchaseItem: ",
442 * new UtilTimerStack.ProfilingBlock<String>() {
443 * public String doProfiling() {
444 * getMyService().purchaseItem(....)
445 * return null;
446 * }
447 * });
448 * </pre>
449 *
450 * @param <T> any return value if there's one.
451 * @param name profile name
452 * @param block code block subjected to profiling
453 * @return T
454 * @throws Exception
455 */
456 public static <T> T profile(String name, ProfilingBlock<T> block) throws Exception {
457 UtilTimerStack.push(name);
458 try {
459 return block.doProfiling();
460 }
461 finally {
462 UtilTimerStack.pop(name);
463 }
464 }
465
466 /**
467 * A callback interface where code subjected to profile is to be executed. This eliminates the need
468 * of coding boiler code that does pushing (UtilTimerBean.push(...)) and poping (UtilTimerBean.pop(...))
469 * in a try ... finally ... block.
470 *
471 * @version $Date$ $Id$
472 *
473 * @param <T>
474 */
475 public static interface ProfilingBlock<T> {
476
477 /**
478 * Method that execute the code subjected to profiling.
479 *
480 * @return profiles Type
481 * @throws Exception
482 */
483 T doProfiling() throws Exception;
484 }
485 }
Save This Page