Author: bpoussin Date: 2010-12-08 17:34:23 +0100 (Wed, 08 Dec 2010) New Revision: 1966 Url: http://nuiton.org/repositories/revision/nuiton-utils/1966 Log: add TimeTrace class to trace time spent between to point Added: trunk/src/main/java/org/nuiton/util/TimeTrace.java Added: trunk/src/main/java/org/nuiton/util/TimeTrace.java =================================================================== --- trunk/src/main/java/org/nuiton/util/TimeTrace.java (rev 0) +++ trunk/src/main/java/org/nuiton/util/TimeTrace.java 2010-12-08 16:34:23 UTC (rev 1966) @@ -0,0 +1,131 @@ +package org.nuiton.util; + +import java.util.HashMap; +import java.util.Map; +import org.apache.commons.logging.Log; +import org.apache.commons.logging.LogFactory; + +/** + * Cette classe permet de facilement trace le temps d'execution entre deux points + * + * usage + * <pre> + * TimeTrace timeTrace = new TimeTrace(5000, 1000); + * + * + * long start = timeTrace.getTime(); + * ... + * // do some work + * ... + * timeTrace.add(start, "do some work"); + * + * + * System.out.println ("time: " + timeTrace.getCallCount()); + * </pre> + * + * @author poussin + * @version $Revision$ + * + * Last update: $Date$ + * by : $Author$ + */ +public class TimeTrace { + + /** to use log facility, just put in your code: log.info(\"...\"); */ + private Log log = LogFactory.getLog(TimeTrace.class); + + static public class CallStat { + long callNumber = 0; + long callTime = 0; + + @Override + public String toString() { + String callTimeString = + StringUtil.convertTime(callTime); + String avgTimeString = + StringUtil.convertTime((callTime/ callNumber)); + return String.format("total call %s, total time %s, avg time %s", + callNumber, callTimeString, avgTimeString); + } + + } + + /** time to trigger log time in info level (ns) */ + protected long timeToLogInfo = 1000; + /** time to trigger log time in warn level (ns) */ + protected long timeToLogWarn = 3000; + + /** for each method of all proxies, keep number of call */ + protected Map<String, CallStat> callCount = new HashMap<String, CallStat>(); + + public TimeTrace() { + } + + /** + * + * @param timeToLogInfo time in milliseconde after that we log info + * @param timeToLogWarn time in milliseconde after that we log warn + */ + public TimeTrace(long timeToLogInfo, long timeToLogWarn) { + this.timeToLogInfo = timeToLogInfo * 1000000; // convert ms -> ns + this.timeToLogWarn = timeToLogWarn * 1000000; // convert ms -> ns + } + + public Map<String, CallStat> getCallCount() { + return callCount; + } + + /** + * return time in format acceptable for {@link #add(timeToLogInfo, timeToLogInfo, null)} + * @return + */ + static public long getTime() { + return System.nanoTime(); + } + + /** + * add new trace, stop time is automaticaly computed + * + * @param startNs time returned by {@link #getTime()} method + * @param methodName key name to store this time + */ + public void add(long startNs, String methodName) { + add(startNs, getTime(), methodName); + } + + /** + * add new trace + * + * @param startNs time returned by {@link #getTime()} method + * @param stopNs time returned by {@link #getTime()} method + * @param methodName key name to store this time + */ + public void add(long startNs, long stopNs, String methodName) { + long time = stopNs - startNs; + + // incremente le nombre d'appel pour cette methode + CallStat calls = callCount.get(methodName); + if (calls == null) { + // is not thread safe, but if we lose one or two call, is not importante + calls = new CallStat(); + callCount.put(methodName, calls); + } + calls.callNumber++; + calls.callTime += time; + + // affiche le temps de l'appel si necessaire + String timeString = StringUtil.convertTime(time); + String msg = String.format("[%s] for method %s (%s)", + timeString, methodName, calls); + + if (time > timeToLogWarn && log.isWarnEnabled()) { + log.warn(msg); + } else if (time > timeToLogInfo && log.isInfoEnabled()) { + log.info(msg); + } else if (log.isDebugEnabled()) { + log.debug(msg); + } + + } + +}