Author: bpoussin Date: 2011-02-23 13:00:57 +0100 (Wed, 23 Feb 2011) New Revision: 2085 Url: http://nuiton.org/repositories/revision/nuiton-utils/2085 Log: Evolution #1353: enhance TimeTrace to permit to use it like log Evolution #1354: enhance TimeTrace to permit to add message and chain add call Evolution #1355: Rename TimeTrace to TimeLog Added: trunk/nuiton-utils/src/main/java/org/nuiton/util/TimeLog.java Modified: trunk/nuiton-utils/src/main/java/org/nuiton/util/TimeTrace.java Added: trunk/nuiton-utils/src/main/java/org/nuiton/util/TimeLog.java =================================================================== --- trunk/nuiton-utils/src/main/java/org/nuiton/util/TimeLog.java (rev 0) +++ trunk/nuiton-utils/src/main/java/org/nuiton/util/TimeLog.java 2011-02-23 12:00:57 UTC (rev 2085) @@ -0,0 +1,241 @@ +/* + * #%L + * Nuiton Utils + * + * $Id$ + * $HeadURL$ + * %% + * Copyright (C) 2004 - 2010 CodeLutin, Benjamin POUSSIN + * %% + * This program is free software: you can redistribute it and/or modify + * it under the terms of the GNU Lesser General Public License as + * published by the Free Software Foundation, either version 3 of the + * License, or (at your option) any later version. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Lesser Public License for more details. + * + * You should have received a copy of the GNU General Lesser Public + * License along with this program. If not, see + * <http://www.gnu.org/licenses/lgpl-3.0.html>. + * #L% + */ +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> + * final static private Log log = LogFactory.getLog(MyClass.class); + * final static private TimeLog timeLog = new TimeLog(MyClass.class, 5000, 1000); + * + * + * long start = timeLog.getTime(); + * ... + * // do some work + * ... + * start = timeLog.log(start, "MyMethod step 1", "do some work"); + * ... + * // do some work + * ... + * timeLog.log(start, "MyMethod step 2", "do other work"); + * + * + * System.out.println ("time: " + timeLog.getCallCount()); + * </pre> + * + * You can configure log level in configuration file with: + * log4j.logger.org.codelutin.MyClass=DEBUG + * log4j.logger.org.codelutin.MyClass.TimeLog=INFO + * + * @see CallAnalyse + * @author poussin + * @version $Revision: 1985 $ + * @since 2.1 + * + * Last update: $Date: 2010-12-23 12:45:57 +0100 (jeu. 23 déc. 2010) $ + * by : $Author: sletellier $ + */ +public class TimeLog { + + /** to use log facility, just put in your code: log.info(\"...\"); */ + final static private Log log = LogFactory.getLog(TimeLog.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); + } + + } + + /** loggueur used to log time */ + protected Log timeLog; + /** time to trigger log time in info level (ns) (default: 1s) */ + protected long timeToLogInfo = 1000l * 1000000l; + /** time to trigger log time in warn level (ns) (default: 3s) */ + protected long timeToLogWarn = 3000l * 1000000l; + + /** for each method of all proxies, keep number of call */ + protected Map<String, CallStat> callCount = new HashMap<String, CallStat>(); + + /** + * + * @param logTime log used to log time message. + */ + protected TimeLog(Log logTime) { + this.timeLog = logTime; + } + + /** + * + * @param logName log category used to log time message. This category must + * be category used to log message in classe that use this TimeLog + * (normaly class name). TimeLog is added at the end. + */ + public TimeLog(String logName) { + this(LogFactory.getLog(logName + ".TimeLog")); + } + + /** + * @param logName log category used to log time message. This category must + * be category used to log message in classe that use this TimeLog + * (normaly class name) + * @since 2.1 + */ + public TimeLog(Class logName) { + this(logName.getName()); + } + + /** + * + * @param logName log category used to log time message. This category must + * be category used to log message in classe that use this TimeLog + * (normaly class name) + * @param timeToLogInfo time in milliseconde after that we log info + * @param timeToLogWarn time in milliseconde after that we log warn + */ + public TimeLog(String logName, long timeToLogInfo, long timeToLogWarn) { + this(logName); + setTimeToLogInfo(timeToLogInfo); + setTimeToLogWarn(timeToLogWarn); + } + + /** + * + * @param logName log category used to log time message. This category must + * be category used to log message in classe that use this TimeLog + * (normaly class name) + * @param timeToLogInfo time in milliseconde after that we log info + * @param timeToLogWarn time in milliseconde after that we log warn + */ + public TimeLog(Class logName, long timeToLogInfo, long timeToLogWarn) { + this(logName.getName(), timeToLogInfo, timeToLogWarn); + } + + /** + * + * @param timeToLogInfoMs time in milliseconde after that we log info + */ + public void setTimeToLogInfo(long timeToLogInfoMs) { + this.timeToLogInfo = timeToLogInfoMs * 1000000l; // convert ms -> ns + } + + /** + * + * @param timeToWarnInfoMs time in milliseconde after that we log warn + */ + public void setTimeToLogWarn(long timeToLogWarnMs) { + this.timeToLogWarn = timeToLogWarnMs * 1000000l; // 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 log(long startNs, String methodName) { + log(startNs, getTime(), methodName, ""); + } + + /** + * add new trace, stop time is automaticaly computed + * + * @param startNs time returned by {@link #getTime()} method + * @param methodName key name to store this time + * @param msg message to add to log + * @return time used as stop time, this permit to chain many add in same + * method to trace time. + */ + public long log(long startNs, String methodName, String msg) { + long result = log(startNs, getTime(), methodName, msg); + return result; + } + + /** + * 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 + * @param msg message to add to log + * @return time used as stop time (stopNs) + */ + public long log(long startNs, long stopNs, String methodName, String msg) { + 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 message = String.format("[%s] for method '%s', %s (%s)", + timeString, methodName, msg, calls); + + if (time > timeToLogWarn && timeLog.isWarnEnabled()) { + timeLog.warn(message); + } else if (time > timeToLogInfo && timeLog.isInfoEnabled()) { + timeLog.info(message); + } else if (timeLog.isDebugEnabled()) { + timeLog.debug(message); + } + return stopNs; + } + +} Modified: trunk/nuiton-utils/src/main/java/org/nuiton/util/TimeTrace.java =================================================================== --- trunk/nuiton-utils/src/main/java/org/nuiton/util/TimeTrace.java 2011-02-21 11:11:50 UTC (rev 2084) +++ trunk/nuiton-utils/src/main/java/org/nuiton/util/TimeTrace.java 2011-02-23 12:00:57 UTC (rev 2085) @@ -50,10 +50,12 @@ * @see CallAnalyse * @author poussin * @version $Revision$ + * @deprecated since 2.1 use {@link org.nuiton.util.TimeLog} * * Last update: $Date$ * by : $Author$ */ +@Deprecated public class TimeTrace { /** to use log facility, just put in your code: log.info(\"...\"); */