/* | |
* Copyright (c) 2004-2008 QOS.ch | |
* All rights reserved. | |
* | |
* Permission is hereby granted, free of charge, to any person obtaining | |
* a copy of this software and associated documentation files (the | |
* "Software"), to deal in the Software without restriction, including | |
* without limitation the rights to use, copy, modify, merge, publish, | |
* distribute, sublicense, and/or sell copies of the Software, and to | |
* permit persons to whom the Software is furnished to do so, subject to | |
* the following conditions: | |
* | |
* The above copyright notice and this permission notice shall be | |
* included in all copies or substantial portions of the Software. | |
* | |
* THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, | |
* EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF | |
* MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND | |
* NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE | |
* LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION | |
* OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION | |
* WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE. | |
*/ | |
package org.slf4j.profiler; | |
import java.util.ArrayList; | |
import java.util.List; | |
import org.slf4j.Logger; | |
import org.slf4j.Marker; | |
import org.slf4j.MarkerFactory; | |
// + Profiler [BAS] | |
// |-- elapsed time [doX] 0 milliseconds. | |
// |-- elapsed time [doYYYYY] 56 milliseconds. | |
// |--+ Profiler Y | |
// |-- elapsed time [doZ] 21 milliseconds. | |
// |-- elapsed time [doZ] 21 milliseconds. | |
// |-- Total elapsed time [Y] 78 milliseconds. | |
// |-- elapsed time [doZ] 21 milliseconds. | |
// |-- Total elapsed time [BAS] 78 milliseconds. | |
/** | |
* A poor man's profiler to measure the time elapsed performing | |
* some lengthy task. | |
* | |
* @author Ceki Gülcü | |
*/ | |
public class Profiler implements TimeInstrument { | |
final static String PROFILER_MARKER_NAME = "PROFILER"; | |
final static int MIN_SW_NAME_LENGTH = 24; | |
final static int MIN_SW_ELAPSED_TIME_NUMBER_LENGTH = 9; | |
final String name; | |
final StopWatch globalStopWatch; | |
//List<StopWatch> stopwatchList = new ArrayList<StopWatch>(); | |
List<TimeInstrument> childTimeInstrumentList = new ArrayList<TimeInstrument>(); | |
// optional field | |
ProfilerRegistry profilerRegistry; | |
//optional field | |
Logger logger; | |
public Profiler(String name) { | |
this.name = name; | |
this.globalStopWatch = new StopWatch(name); | |
} | |
public String getName() { | |
return name; | |
} | |
public ProfilerRegistry getProfilerRegistry() { | |
return profilerRegistry; | |
} | |
public void registerWith(ProfilerRegistry profilerRegistry) { | |
if (profilerRegistry == null) { | |
return; | |
} | |
this.profilerRegistry = profilerRegistry; | |
profilerRegistry.put(this); | |
} | |
public Logger getLogger() { | |
return logger; | |
} | |
public void setLogger(Logger logger) { | |
this.logger = logger; | |
} | |
/** | |
* Starts a child stop watch and stops any previously started time instruments. | |
*/ | |
public void start(String name) { | |
stopLastTimeInstrument(); | |
StopWatch childSW = new StopWatch(name); | |
childTimeInstrumentList.add(childSW); | |
} | |
public Profiler startNested(String name) { | |
stopLastTimeInstrument(); | |
Profiler nestedProfiler = new Profiler(name); | |
nestedProfiler.registerWith(profilerRegistry); | |
nestedProfiler.setLogger(logger); | |
childTimeInstrumentList.add(nestedProfiler); | |
return nestedProfiler; | |
} | |
TimeInstrument getLastTimeInstrument() { | |
if (childTimeInstrumentList.size() > 0) { | |
return childTimeInstrumentList.get(childTimeInstrumentList.size() - 1); | |
} else { | |
return null; | |
} | |
} | |
void stopLastTimeInstrument() { | |
TimeInstrument last = getLastTimeInstrument(); | |
if (last != null) { | |
last.stop(); | |
} | |
} | |
// void stopNestedProfilers() { | |
// for (Object child : childTimeInstrumentList) { | |
// if (child instanceof Profiler) | |
// ((Profiler) child).stop(); | |
// } | |
// } | |
public long elapsedTime() { | |
return globalStopWatch.elapsedTime(); | |
} | |
public TimeInstrument stop() { | |
stopLastTimeInstrument(); | |
globalStopWatch.stop(); | |
return this; | |
} | |
public TimeInstrumentStatus getStatus() { | |
return globalStopWatch.status; | |
} | |
/** | |
* This method is used in tests. | |
*/ | |
void sanityCheck() throws IllegalStateException { | |
if(getStatus() != TimeInstrumentStatus.STOPPED) { | |
throw new IllegalStateException("time instrument ["+getName()+" is not stopped"); | |
} | |
long totalElapsed = globalStopWatch.elapsedTime(); | |
long childTotal = 0; | |
for(TimeInstrument ti: childTimeInstrumentList) { | |
childTotal += ti.elapsedTime(); | |
if(ti.getStatus() != TimeInstrumentStatus.STOPPED) { | |
throw new IllegalStateException("time instrument ["+ti.getName()+" is not stopped"); | |
} | |
if(ti instanceof Profiler) { | |
Profiler nestedProfiler = (Profiler) ti; | |
nestedProfiler.sanityCheck(); | |
} | |
} | |
if(totalElapsed < childTotal) { | |
throw new IllegalStateException("children have a higher accumulated elapsed time"); | |
} | |
} | |
static String TOP_PROFILER_FIRST_PREFIX = "+"; | |
static String NESTED_PROFILER_FIRST_PREFIX = "|---+"; | |
static String TOTAL_ELAPSED = " Total "; | |
static String SUBTOTAL_ELAPSED = " Subtotal "; | |
static String ELAPSED_TIME = " elapsed time "; | |
public void print() { | |
System.out.println(toString()); | |
} | |
@Override | |
public String toString() { | |
DurationUnit du = Util.selectDurationUnitForDisplay(globalStopWatch); | |
return buildProfilerString(du, TOP_PROFILER_FIRST_PREFIX, TOTAL_ELAPSED, ""); | |
} | |
public void log() { | |
Marker profilerMarker = MarkerFactory.getMarker(PROFILER_MARKER_NAME); | |
if(logger == null) { | |
throw new NullPointerException("If you invoke the log() method, then you must associate a logger with this profiler."); | |
} | |
if (logger.isDebugEnabled(profilerMarker)) { | |
DurationUnit du = Util.selectDurationUnitForDisplay(globalStopWatch); | |
String r = buildProfilerString(du, TOP_PROFILER_FIRST_PREFIX, TOTAL_ELAPSED, ""); | |
logger.debug(profilerMarker, SpacePadder.LINE_SEP+r); | |
} | |
} | |
private String buildProfilerString(DurationUnit du, String firstPrefix, String label, String indentation) { | |
StringBuffer buf = new StringBuffer(); | |
buf.append(firstPrefix); | |
buf.append(" Profiler ["); | |
buf.append(name); | |
buf.append("]"); | |
buf.append(SpacePadder.LINE_SEP); | |
for (TimeInstrument child : childTimeInstrumentList) { | |
if (child instanceof StopWatch) { | |
buildStopWatchString(buf, du, ELAPSED_TIME, indentation, (StopWatch) child); | |
} else if (child instanceof Profiler) { | |
Profiler profiler = (Profiler) child; | |
String subString = profiler | |
.buildProfilerString(du, NESTED_PROFILER_FIRST_PREFIX, SUBTOTAL_ELAPSED, indentation + " "); | |
buf.append(subString); | |
buildStopWatchString(buf, du, ELAPSED_TIME, indentation, profiler.globalStopWatch); | |
} | |
} | |
buildStopWatchString(buf, du, label, indentation, globalStopWatch); | |
return buf.toString(); | |
} | |
private static void buildStopWatchString(StringBuffer buf, DurationUnit du, | |
String prefix, String indentation, StopWatch sw) { | |
buf.append(indentation); | |
buf.append("|--"); | |
buf.append(prefix); | |
SpacePadder.leftPad(buf, "[" + sw.getName() + "]", MIN_SW_NAME_LENGTH); | |
buf.append(" "); | |
String timeStr = Util.durationInDurationUnitsAsStr(sw.elapsedTime(), | |
du); | |
SpacePadder.leftPad(buf, timeStr, MIN_SW_ELAPSED_TIME_NUMBER_LENGTH); | |
buf.append(" "); | |
Util.appendDurationUnitAsStr(buf, du); | |
buf.append(SpacePadder.LINE_SEP); | |
} | |
} |