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