1 /**
2 * Copyright 2005-2014 The Kuali Foundation
3 *
4 * Licensed under the Educational Community 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.opensource.org/licenses/ecl2.php
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.kuali.rice.krad.uif.util;
17
18 import java.text.DecimalFormat;
19 import java.util.Date;
20 import java.util.Deque;
21 import java.util.Map;
22 import java.util.Map.Entry;
23 import java.util.concurrent.Callable;
24
25 import org.apache.log4j.Logger;
26
27 /**
28 * Performance monitoring log utility.
29 *
30 * @author Kuali Rice Team (rice.collab@kuali.org)
31 * @version 2.4
32 */
33 public class ProcessLogger {
34
35 private static final Logger LOG = Logger.getLogger(ProcessLogger.class);
36
37 /**
38 * Thread local mapping of process status trackers.
39 */
40 private static final ThreadLocal<Map<String, ProcessStatus>> TL_STAT = new ThreadLocal<Map<String, ProcessStatus>>();
41
42 /**
43 * Tracks statistics and execution count for common operations.
44 *
45 * <p>
46 * ProcessCounter is typically used to clock calls to external systems, such as database and web
47 * service requests.
48 * </p>
49 */
50 private static class ProcessCounter {
51
52 /**
53 * The name of the counter.
54 */
55 private final String name;
56
57 /**
58 * Stack of the start times for currently active executions.
59 */
60 private Deque<Long> start = new java.util.LinkedList<Long>();
61
62 /**
63 * The total count of all executions.
64 */
65 private long count;
66
67 /**
68 * The minimum execution time, calculated among all executions within the same process.
69 */
70 private long min;
71
72 /**
73 * The maximum execution time, calculated among all executions within the same process.
74 */
75 private long max;
76
77 /**
78 * The average (mean) execution time, calculated among all executions within the same
79 * process.
80 */
81 private long avg;
82
83 /**
84 * A detailed description of the execution responsible for the max execution time.
85 */
86 private String longest;
87
88 /**
89 * Create a new counter for use within the current process.
90 *
91 * @param name The name of the counter.
92 */
93 private ProcessCounter(String name) {
94 this.name = name;
95 }
96 }
97
98 /**
99 * Tracks the status of one more processes actively being monitoring on the current Thread.
100 *
101 * <p>
102 * This class represents the internal state of most of ProcessLogger's operations.
103 * </p>
104 */
105 private static class ProcessStatus {
106
107 /**
108 * The name of this process trace.
109 */
110 private final String name;
111
112 /**
113 * The start time the process started.
114 */
115 private final long startTime;
116
117 /**
118 * Heap free space, recorded at the start of the process.
119 */
120 private final long startFree;
121
122 /**
123 * Heap total available space, recorded at the start of the process.
124 */
125 private final long startTot;
126
127 /**
128 * Heap max available space, recorded at the start of the process.
129 */
130 private final long startMax;
131
132 /**
133 * The time of the last trace message reported on this process.
134 */
135 private long lastTime;
136
137 /**
138 * Heap free space, recorded at the time the last trace message was reported on this
139 * process.
140 */
141 private long lastFree;
142
143 /**
144 * Heap total available space, recorded at the time the last trace message was reported on
145 * this process.
146 */
147 private long lastTot;
148
149 /**
150 * Heap max available space, recorded at the time the last trace message was reported on
151 * this process.
152 */
153 private long lastMax;
154
155 /**
156 * The time, in milliseconds, elapsed between the last trace message reported and the
157 * previous report.
158 */
159 private long diffTime;
160
161 /**
162 * The difference in heap free space between the last trace message reported and the
163 * previous report.
164 */
165 private long diffFree;
166
167 /**
168 * The difference in heap total space between the last trace message reported and the
169 * previous report.
170 */
171 private long diffTot;
172
173 /**
174 * Internal mapping of counters tracked on this process.
175 */
176 private Map<String, ProcessCounter> counters = new java.util.LinkedHashMap<String, ProcessCounter>();
177
178 /**
179 * Internal mapping of ntrace counters.
180 *
181 * <p>
182 * These counters are used for detecting excessive execution counts of operations that are
183 * typically fast, but may become expensive with a high number of executions. For example,
184 * ntrace counts may be used to track excessive object creation.
185 * </p>
186 */
187 private Map<String, Long> ntraceCount = new java.util.TreeMap<String, Long>();
188
189 /**
190 * Internal mapping of ntrace thresholds.
191 *
192 * <p>
193 * Associated with ntraceCount, this map defines thresholds below which not to report counts.
194 * </p>
195 */
196 private Map<String, Long> ntraceThreshold = new java.util.HashMap<String, Long>();
197
198 /**
199 * Verbose operation flag.
200 *
201 * <p>
202 * When true, all trace messages will be included regardless of elapsed time. When false,
203 * trace messages will only be included when elapsed time is 1 or more milliseconds.
204 * </p>
205 *
206 * <p>
207 * By default, verbose is true when debugging is enabled via {@link #LOG}.
208 * </p>
209 */
210 private boolean verbose = LOG.isDebugEnabled();
211
212 /**
213 * StringBuilder for constructing the trace message for reporting via log4j.
214 */
215 private StringBuilder traceBuffer = new StringBuilder();
216
217 /**
218 * StringBuilder for collecting extra information to included at the end of the trace.
219 */
220 private StringBuilder extra = new StringBuilder();
221
222 /**
223 * Create a status tracker for a new process.
224 *
225 * @param name The name of the process.
226 */
227 private ProcessStatus(String name) {
228 this.name = name;
229 this.startTime = System.currentTimeMillis();
230 this.startFree = Runtime.getRuntime().freeMemory();
231 this.startTot = Runtime.getRuntime().totalMemory();
232 this.startMax = Runtime.getRuntime().maxMemory();
233 this.lastTime = startTime;
234 this.lastFree = startFree;
235 this.lastTot = startTot;
236 this.lastMax = startMax;
237 }
238
239 /**
240 * Report that time has elapsed on the process.
241 * <p>
242 * This method updates the following fields based on the current system runtime.
243 * <ul>
244 * <li>{@link #diffTime}</li>
245 * <li>{@link #diffFree}</li>
246 * <li>{@link #diffTot}</li>
247 * <li>{@link #lastTime}</li>
248 * <li>{@link #lastFree}</li>
249 * <li>{@link #lastTot}</li>
250 * <li>{@link #lastMax}</li>
251 * </ul>
252 */
253 private void elapse() {
254 long nTime = System.currentTimeMillis();
255 long nFree = Runtime.getRuntime().freeMemory();
256 long nTot = Runtime.getRuntime().totalMemory();
257 long nMax = Runtime.getRuntime().maxMemory();
258 diffTime = nTime - lastTime;
259 diffFree = nFree - lastFree;
260 diffTot = nTot - lastTot;
261 lastTime = nTime;
262 lastFree = nFree;
263 lastTot = nTot;
264 lastMax = nMax;
265 }
266
267 /**
268 * Mark the start of a new countable operation in the current process.
269 *
270 * @param name The name of the process counter.
271 */
272 private void countBegin(String name) {
273 ProcessCounter pc = counters.get(name);
274 if (pc == null) {
275 pc = new ProcessCounter(name);
276 counters.put(name, pc);
277 }
278 pc.start.push(new Long(System.currentTimeMillis()));
279 }
280
281 /**
282 * Mark the end of a countable operation previously reported via {@link #countBegin(String)}
283 * .
284 *
285 * @param name The name of the process counter.
286 * @param detail Details on the operation that just ended.
287 * @return The process counter.
288 */
289 private ProcessCounter countEnd(String name, String detail) {
290 ProcessCounter pc = counters.get(name);
291 if (pc == null || pc.start.isEmpty()) {
292 return null;
293 }
294
295 long start = pc.start.pop();
296 long elapsed = System.currentTimeMillis() - start;
297
298 if (elapsed < pc.min || pc.count == 0L) {
299 pc.min = elapsed;
300 }
301
302 if (elapsed > pc.max) {
303 pc.max = elapsed;
304 pc.longest = detail;
305 }
306
307 pc.count++;
308 pc.avg = (pc.avg * (pc.count - 1) + elapsed) / pc.count;
309
310 return pc;
311 }
312
313 /**
314 * Write a trace header on the process trace.
315 *
316 * @param name The name of the process trace.
317 * @param processDescription A description of the process trace.
318 */
319 private void appendTraceHeader(String name, String processDescription) {
320 // Write a description of the process to the trace buffer.
321 traceBuffer.append("KRAD Process Trace (");
322 traceBuffer.append(name);
323 traceBuffer.append("): ");
324 traceBuffer.append(processDescription);
325
326 // Write stack information related to method controlling the callable process.
327 StackTraceElement[] stackTrace = Thread.currentThread().getStackTrace();
328 String callerClassName = stackTrace[3].getClassName();
329 int indexOfPeriod = callerClassName.lastIndexOf('.');
330 String callerPackageName = "";
331 if (indexOfPeriod != -1) {
332 callerPackageName = callerClassName.substring(0, indexOfPeriod);
333 }
334 int stackTraceIndex = 3;
335 while (stackTraceIndex < stackTrace.length - 1
336 && (stackTrace[stackTraceIndex].getClassName().startsWith("sun.")
337 || stackTrace[stackTraceIndex].getClassName().startsWith("java.")
338 || stackTrace[stackTraceIndex].getClassName().startsWith(
339 ProcessLogger.class.getPackage().getName()) || stackTrace[stackTraceIndex]
340 .getClassName().startsWith(callerPackageName))) {
341 if (!ProcessLogger.class.getName().equals(stackTrace[stackTraceIndex].getClassName())) {
342 traceBuffer.append("\n at ").append(stackTrace[stackTraceIndex]);
343 }
344 stackTraceIndex++;
345 }
346 traceBuffer.append("\n at ").append(stackTrace[stackTraceIndex]);
347
348 // Write initial heap state and start time.
349 traceBuffer.append("\nInitial Memory Usage: ");
350 traceBuffer.append(memoryToString(startFree, startTot,
351 startMax));
352
353 if (LOG.isInfoEnabled() && verbose) {
354 LOG.debug("Processing Started\n" + traceBuffer.toString());
355 }
356 }
357
358 /**
359 * Write a log message on this process trace.
360 *
361 * @param message The message to write.
362 */
363 public void appendTraceMessage(String message) {
364 if (LOG.isDebugEnabled() && verbose) {
365 LOG.debug(message
366 + " ("
367 + name
368 + ")\nElapsed Time: "
369 + intervalToString(diffTime)
370 + "\nMemory Usage: "
371 + memoryToString(lastFree, lastTot,
372 lastMax)
373 + "\nMemory Delta: "
374 + memoryToString(diffFree, lastTot,
375 lastMax) + " - tot delta: "
376 + sizeToString(diffTot));
377 }
378
379 if (LOG.isInfoEnabled() && (verbose || diffTime > 0L)) {
380 traceBuffer.append('\n');
381
382 if (message.length() < 40) {
383 traceBuffer.append(message);
384 for (int i = message.length(); i < 40; i++) {
385 traceBuffer.append('.');
386 }
387 } else {
388 traceBuffer.append(message.substring(0, 40));
389 }
390
391 traceBuffer.append(intervalToString(diffTime));
392 traceBuffer.append(' ');
393 traceBuffer.append(intervalToString(lastTime
394 - startTime));
395 traceBuffer.append(' ');
396 traceBuffer.append(sizeToString(lastFree));
397 traceBuffer.append(' ');
398 traceBuffer.append(sizeToString(diffFree));
399 }
400 }
401
402 /**
403 * Write a trace footer on the process trace.
404 */
405 public void appendTraceFooter() {
406 traceBuffer.append('\n');
407 String message = "Processing Complete";
408 traceBuffer.append(message);
409 for (int i = message.length(); i < 40; i++) {
410 traceBuffer.append('.');
411 }
412 traceBuffer.append(intervalToString(diffTime));
413 traceBuffer.append(' ');
414 traceBuffer.append(intervalToString(lastTime
415 - startTime));
416 traceBuffer.append(' ');
417 traceBuffer.append(sizeToString(lastFree));
418 traceBuffer.append(' ');
419 traceBuffer.append(sizeToString(diffFree));
420 if (!ntraceCount.isEmpty()) {
421 traceBuffer.append("\nMonitors:");
422 for (Entry<String, Long> ce : ntraceCount.entrySet()) {
423
424 Long threshold = ntraceThreshold.get(ce.getKey());
425 if (threshold != null && threshold >= ce.getValue()) {
426 continue;
427 }
428
429 traceBuffer.append("\n ");
430 StringBuilder sb = new StringBuilder(ce.getKey());
431 int iocc = sb.indexOf("::");
432 if (iocc == -1)
433 sb.append(":" + ce.getValue());
434 else
435 sb.insert(iocc + 1, ce.getValue());
436 traceBuffer.append(sb);
437 }
438 }
439 if (!counters.isEmpty()) {
440 traceBuffer.append("\nCounters:");
441 for (ProcessCounter pc : counters.values()) {
442 traceBuffer.append("\n ");
443 traceBuffer.append(pc.name);
444 traceBuffer.append(": ");
445 traceBuffer.append(pc.count);
446 traceBuffer.append(" (");
447 traceBuffer.append(intervalToString(pc.min));
448 traceBuffer.append("/");
449 traceBuffer.append(intervalToString(pc.max));
450 traceBuffer.append("/");
451 traceBuffer.append(intervalToString(pc.avg));
452 traceBuffer.append(")");
453 if (pc.longest != null && !"".equals(pc.longest)) {
454 traceBuffer.append("\n longest : ");
455 traceBuffer.append(pc.longest);
456 }
457 }
458 }
459 traceBuffer.append("\nElapsed Time: ");
460 traceBuffer.append(intervalToString(lastTime
461 - startTime));
462 traceBuffer.append("\nMemory Usage: ");
463 traceBuffer.append(memoryToString(lastFree, lastTot,
464 lastMax));
465 traceBuffer.append("\nMemory Delta: ");
466 traceBuffer.append(memoryToString(lastFree
467 - startFree, lastTot, lastMax));
468 traceBuffer.append(" - tot delta: ");
469 traceBuffer.append(sizeToString(lastTot - startTot));
470 }
471
472 }
473
474 /**
475 * Print a human readable time duration.
476 *
477 * @param millis The number of milliseconds.
478 * @return A human readable representation of the time interval represented by millis.
479 */
480 public static String intervalToString(long millis) {
481 DecimalFormat df = new DecimalFormat("000");
482 StringBuilder sb = new StringBuilder();
483 sb.append('.');
484 sb.append(df.format(millis % 1000));
485 df.applyPattern("00");
486 long sec = millis / 1000;
487 sb.insert(0, df.format(sec % 60));
488 long min = sec / 60;
489 sb.insert(0, ':');
490 sb.insert(0, df.format(min % 60));
491 long hours = min / 60;
492 if (hours > 0) {
493 sb.insert(0, ':');
494 sb.insert(0, df.format(hours % 24));
495 }
496 long days = hours / 24;
497 if (days > 0) {
498 sb.insert(0, " days, ");
499 sb.insert(0, days);
500 }
501
502 return sb.toString();
503 }
504
505 /**
506 * The steps for printing sizes.
507 */
508 private static final String[] SIZE_INTERVALS = new String[]{"k", "M",
509 "G", "T", "E",};
510
511 /**
512 * Print a human readable size.
513 *
514 * @param bytes The number of bytes.
515 * @return A human readable representation of the size.
516 */
517 public static String sizeToString(long bytes) {
518 DecimalFormat df = new DecimalFormat("000");
519 StringBuilder sb = new StringBuilder();
520 int i = -1;
521 int mod = 0;
522
523 if (bytes < 0) {
524 sb.append('-');
525 bytes = Math.abs(bytes);
526 }
527
528 while (bytes / 1024 > 0 && i < SIZE_INTERVALS.length) {
529 i++;
530 mod = (int) (bytes % 1024);
531 bytes /= 1024;
532 }
533 sb.append(bytes);
534
535 if (mod > 0) {
536 sb.append('.');
537 sb.append(df.format(mod * 1000 / 1024));
538 }
539
540 if (i >= 0) {
541 sb.append(SIZE_INTERVALS[i]);
542 }
543
544 return sb.toString();
545 }
546
547 /**
548 * Get a human readable representation of the system memory.
549 *
550 * @param free free heap memory, in bytes
551 * @param tot total heap memory, in bytes
552 * @param max maximum total heap memory, in bytes
553 *
554 * @return A human readable representation of the system memory.
555 */
556 public static String memoryToString(long free, long tot, long max) {
557 StringBuilder sb = new StringBuilder();
558 sb.append(sizeToString(free));
559 sb.append('/');
560 sb.append(sizeToString(tot));
561 sb.append('/');
562 sb.append(sizeToString(max));
563 sb.append(" - ");
564 sb.append(free * 100 / tot);
565 sb.append("% free");
566 return sb.toString();
567 }
568
569 /**
570 * Follow a callable process using the system default verbose setting and checked exception
571 * handling.
572 *
573 * @param <T> callable return type
574 * @param name The name of the process.
575 * @param processDescription A message describing the process to report at the top of the trace.
576 * @param callableProcess The callable process.
577 * @return The result of calling the process.
578 * @throws IllegalStateException If checked exception occurs within the callable process.
579 */
580 public static <T> T safeFollow(final String name, final String processDescription,
581 final Callable<T> callableProcess) {
582 try {
583 return follow(name, processDescription, null, callableProcess);
584 } catch (Exception e) {
585 if (e instanceof RuntimeException) {
586 throw (RuntimeException) e;
587 } else {
588 throw new IllegalStateException("Error in followed process " + name + " - " + processDescription, e);
589 }
590 }
591 }
592
593 /**
594 * Follow a callable process with checked exception handling.
595 *
596 * @param <T> callable return type
597 * @param name The name of the process.
598 * @param processDescription A message describing the process to report at the top of the trace.
599 * @param verbose Verbose operation flag, see {@link ProcessStatus#verbose}.
600 * @param callableProcess The callable process.
601 * @return The result of calling the process.
602 * @throws IllegalStateException If checked exception occurs within the callable process.
603 */
604 public static <T> T safeFollow(final String name, final String processDescription,
605 final Boolean verbose, final Callable<T> callableProcess) {
606 try {
607 return follow(name, processDescription, verbose, callableProcess);
608 } catch (Exception e) {
609 if (e instanceof RuntimeException) {
610 throw (RuntimeException) e;
611 } else {
612 throw new IllegalStateException("Error in followed process " + name + " - " + processDescription, e);
613 }
614 }
615 }
616
617 /**
618 * Follow a callable process using the system default verbose setting.
619 *
620 * @param <T> callable return type
621 * @param name The name of the process.
622 * @param processDescription A message describing the process to report at the top of the trace.
623 * @param callableProcess The callable process.
624 * @return The result of calling the process.
625 * @throws Exception from {@link Callable#call()}
626 */
627 public static <T> T follow(String name, String processDescription, Callable<T> callableProcess)
628 throws Exception {
629 return follow(name, processDescription, null, callableProcess);
630 }
631
632 /**
633 * Follow a callable process.
634 *
635 * @param <T> callable return type
636 * @param name The name of the process.
637 * @param processDescription A message describing the process to report at the top of the trace.
638 * @param verbose True to note every trace entry, false to only note those that take longer than 1ms.
639 * @param callableProcess The callable process.
640 * @return The result of calling the process.
641 * @throws Exception from {@link Callable#call()}
642 */
643 public static <T> T follow(String name, String processDescription, Boolean verbose,
644 Callable<T> callableProcess) throws Exception {
645 // When logging is not at least info enabled, process tracing has no effect - short circuit.
646 if (!LOG.isInfoEnabled()) {
647 return callableProcess.call();
648 }
649
650 // Ensure that statistics are not already active for a process with the same name.
651 assert TL_STAT.get() == null || TL_STAT.get().get(name) == null;
652
653 // Bind a new status tracking map to the current thread, if not already bound.
654 if (TL_STAT.get() == null) {
655 TL_STAT.set(new java.util.HashMap<String, ProcessStatus>());
656 }
657
658 // Create a new status tracker for monitoring this process.
659 ProcessStatus processStatus = new ProcessStatus(name);
660 if (verbose != null) {
661 processStatus.verbose = verbose;
662 }
663
664 try {
665 // Bind the status tracker to the current thread.
666 TL_STAT.get().put(name, processStatus);
667
668 processStatus.appendTraceHeader(name, processDescription);
669
670 // Call the process.
671 return callableProcess.call();
672
673 } finally {
674 // Clear the thread state to prevent memory growth.
675 if (TL_STAT.get() != null) {
676 TL_STAT.get().remove(name);
677 if (TL_STAT.get().isEmpty())
678 TL_STAT.remove();
679 }
680
681 // Calculate time and heap utilization since the last trace message.
682 processStatus.elapse();
683 processStatus.appendTraceFooter();
684
685 // Write process trace at INFO level
686 LOG.info(processStatus.traceBuffer.toString());
687 }
688 }
689
690 /**
691 * Determine if any process traces are active on the current thread.
692 *
693 * @return True if any process traces are active on the current thread, false if not.
694 */
695 public static boolean isTraceActive() {
696 return TL_STAT.get() != null && !TL_STAT.get().isEmpty();
697 }
698
699 /**
700 * Determine if a process trace is active on the current thread.
701 *
702 * @param name The name of the process trace.
703 * @return True if the named process trace is active on the current thread, false if not.
704 */
705 public static boolean isTraceActive(String name) {
706 return TL_STAT.get() != null && TL_STAT.get().containsKey(name);
707 }
708
709 /**
710 * Determine if the named process is active on the current thread with the verbose flag set to
711 * true.
712 *
713 * @param name The name of the process trace.
714 * @return True if the named process trace is active on the current thread with the verbose flag
715 * set to true, false if not.
716 */
717 public static boolean isVerbose(String name) {
718 ProcessStatus processStatus = TL_STAT.get() == null ? null : TL_STAT.get().get(
719 name);
720 return processStatus != null && processStatus.verbose;
721 }
722
723 /**
724 * Modify the verbose flag on a process trace active on the current thread.
725 *
726 * <p>
727 * This method has no impact if a process trace with the given name is not active.
728 * </p>
729 *
730 * @param name The name of the process trace.
731 * @param verbose The verbose flag setting to apply to the named process trace.
732 */
733 public static void setVerbose(String name, boolean verbose) {
734 ProcessStatus ps = TL_STAT.get() == null ? null : TL_STAT.get().get(
735 name);
736 if (ps != null) {
737 ps.verbose = verbose;
738 }
739 }
740
741 /**
742 * Report a trace message on all process traces active on the current thread.
743 *
744 * <p>
745 * The first 40 characters of the message will be printed on the traces along with timing and
746 * heap utilization statistics.
747 * </p>
748 *
749 * <p>
750 * When debug logging is enabled, the entire message will be printed via log4j at the DEBUG
751 * level.
752 * </p>
753 *
754 * @param message The message to report on the trace.
755 */
756 public static void trace(String message) {
757 if (TL_STAT.get() != null) {
758 for (String k : TL_STAT.get().keySet()) {
759 trace(k, message);
760 }
761 }
762 }
763
764 /**
765 * Report a trace message on a process trace, if active on the current thread.
766 *
767 * <p>
768 * The first 40 characters of the message will be printed on the trace along with timing and
769 * heap utilization statistics.
770 * </p>
771 *
772 * <p>
773 * When debug logging is enabled, the entire message will be printed via log4j at the DEBUG
774 * level.
775 * </p>
776 *
777 * @param name The name of the process trace.
778 * @param message The message to report on the trace.
779 */
780 public static void trace(String name, String message) {
781 ProcessStatus processStatus = TL_STAT.get() == null ? null : TL_STAT.get().get(
782 name);
783 if (processStatus != null) {
784 processStatus.elapse();
785 processStatus.appendTraceMessage(message);
786 }
787 }
788
789 /**
790 * Count instances of a typically fast operation that may become expensive given a high number
791 * of executions.
792 *
793 * <p>
794 * When the specified number of instances of the same operation have been counted, then a
795 * message indicating the execution count will be added to the process trace.
796 * </p>
797 *
798 * @param prefix The message to report before the count.
799 * @param suffix The message to report after the count.
800 * @param interval The number of instances to count between reports on the process trace.
801 * @return The execution count of the operation on trace with the highest number of executions.
802 */
803 public static long ntrace(String prefix, String suffix, long interval) {
804 return ntrace(prefix, suffix, interval, 0L);
805 }
806
807 /**
808 * Count instances of a typically fast operation that may become expensive given a high number
809 * of executions.
810 *
811 * <p>
812 * When the specified number of instances of the same operation have been counted, then a
813 * message indicating the execution count will be added to the process trace.
814 * </p>
815 *
816 * @param prefix The message to report before the count.
817 * @param suffix The message to report after the count.
818 * @param interval The number of instances to count between reports on the process trace.
819 * @param threshold The number of instances below which not to report monitored counts.
820 * @return The execution count of the operation on trace with the highest number of executions.
821 */
822 public static long ntrace(String prefix, String suffix, long interval, long threshold) {
823 long rv = 0L;
824 if (TL_STAT.get() != null) {
825 for (String k : TL_STAT.get().keySet()) {
826 rv = Math.max(rv, ntrace(k, prefix, suffix, interval, threshold));
827 }
828 }
829
830 return rv;
831 }
832
833 /**
834 * Count instances of a typically fast operation that may become expensive given a high number
835 * of executions.
836 *
837 * <p>
838 * When the specified number of instances of the same operation have been counted, then a
839 * message indicating the execution count will be added to the process trace.
840 * </p>
841 *
842 * @param name The name of the trace.
843 * @param prefix The message to report before the count.
844 * @param suffix The message to report after the count.
845 * @param interval The number of instances to count between reports on the process trace.
846 * @return The execution count of the operation on the named trace.
847 */
848 public static long ntrace(String name, String prefix, String suffix,
849 long interval) {
850 return ntrace(name, prefix, suffix, interval, 0L);
851 }
852
853 /**
854 * Count instances of a typically fast operation that may become expensive given a high number
855 * of executions.
856 *
857 * <p>
858 * When the specified number of instances of the same operation have been counted, then a
859 * message indicating the execution count will be added to the process trace.
860 * </p>
861 *
862 * @param name The name of the trace.
863 * @param prefix The message to report before the count.
864 * @param suffix The message to report after the count.
865 * @param interval The number of instances to count between reports on the process trace.
866 * @param threshold The number of instances below which not to report monitored counts.
867 * @return The execution count of the operation on the named trace.
868 */
869 public static long ntrace(String name, String prefix, String suffix,
870 long interval, long threshold) {
871 ProcessStatus processStatus = TL_STAT.get() == null ? null : TL_STAT.get().get(
872 name);
873 String nTraceCountKey = prefix + suffix;
874 Long nTraceCount = processStatus.ntraceCount.get(nTraceCountKey);
875
876 if (nTraceCount == null) {
877 nTraceCount = 0L;
878 }
879
880 processStatus.ntraceCount.put(nTraceCountKey, ++nTraceCount);
881
882 if (threshold > 0) {
883 processStatus.ntraceThreshold.put(nTraceCountKey, threshold);
884 }
885
886 if (nTraceCount % interval == 0) {
887 String msg = prefix + nTraceCount + suffix;
888 trace(msg);
889 if (LOG.isDebugEnabled()) {
890 LOG.debug(msg, new Throwable());
891 }
892 }
893
894 return nTraceCount;
895 }
896
897 /**
898 * Mark the start of a new countable operation on all active process traces.
899 *
900 * @param name The name of the process counter.
901 */
902 public static void countBegin(String name) {
903 if (TL_STAT.get() != null) {
904 for (String k : TL_STAT.get().keySet()) {
905 countBegin(k, name);
906 }
907 }
908 }
909
910 /**
911 * Mark the start of a new countable operation on an active process trace.
912 *
913 * @param traceName The name of the process trace.
914 * @param name The name of the process counter.
915 */
916 public static void countBegin(String traceName, String name) {
917 ProcessStatus ps = TL_STAT.get() == null ? null : TL_STAT.get().get(
918 traceName);
919 if (ps != null) {
920 ps.countBegin(name);
921 }
922 }
923
924 /**
925 * Mark the end of a countable operation previously reported via {@link #countBegin(String)} .
926 *
927 * @param name The name of the process counter.
928 * @param detail Details on the operation that just ended.
929 */
930 public static void countEnd(String name, String detail) {
931 if (TL_STAT.get() != null) {
932 for (String k : TL_STAT.get().keySet()) {
933 countEnd(k, name, detail);
934 }
935 }
936 }
937
938 /**
939 * Mark the end of a countable operation previously reported via
940 * {@link #countBegin(String, String)} .
941 *
942 * @param traceName The name of the process trace.
943 * @param name The name of the process counter.
944 * @param detail Details on the operation that just ended.
945 */
946 public static void countEnd(String traceName, String name,
947 String detail) {
948 ProcessStatus processStatus = TL_STAT.get() == null ? null : TL_STAT.get().get(
949 traceName);
950 if (processStatus != null) {
951 processStatus.countEnd(name, detail);
952 }
953 }
954
955 /**
956 * Append an informational message to a process trace.
957 *
958 * <p>
959 * The message will additionally be logged at the INFO level.
960 * </p>
961 *
962 * @param traceName The name of the process trace.
963 * @param message The information message.
964 */
965 public static void addExtra(String traceName, Object message) {
966 ProcessStatus processStatus = TL_STAT.get() == null ? null : TL_STAT.get().get(
967 traceName);
968 if (processStatus == null) {
969 return;
970 }
971 StringBuilder sb = new StringBuilder();
972 sb.append("Information Message Reported at ");
973 sb.append(new Date());
974 sb.append(":\n");
975 sb.append(message);
976 LOG.info(sb.toString());
977 processStatus.extra.append(sb);
978 processStatus.extra.append("\n\n");
979 }
980
981 }