1 /* 2 * #%L 3 * Nuiton Utils 4 * %% 5 * Copyright (C) 2004 - 2010 CodeLutin, Benjamin POUSSIN 6 * %% 7 * This program is free software: you can redistribute it and/or modify 8 * it under the terms of the GNU Lesser General Public License as 9 * published by the Free Software Foundation, either version 3 of the 10 * License, or (at your option) any later version. 11 * 12 * This program is distributed in the hope that it will be useful, 13 * but WITHOUT ANY WARRANTY; without even the implied warranty of 14 * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the 15 * GNU General Lesser Public License for more details. 16 * 17 * You should have received a copy of the GNU General Lesser Public 18 * License along with this program. If not, see 19 * <http://www.gnu.org/licenses/lgpl-3.0.html>. 20 * #L% 21 */ 22 package org.nuiton.util; 23 24 import org.apache.commons.logging.Log; 25 import org.apache.commons.logging.LogFactory; 26 27 import java.util.HashMap; 28 import java.util.Map; 29 30 /** 31 * Cette classe permet de facilement trace le temps d'execution entre deux points 32 * 33 * usage 34 * <pre> 35 * final private static final Log log = LogFactory.getLog(MyClass.class); 36 * final static private TimeLog timeLog = new TimeLog(MyClass.class, 5000, 1000); 37 * 38 * 39 * long start = timeLog.getTime(); 40 * ... 41 * // do some work 42 * ... 43 * start = timeLog.log(start, "MyMethod step 1", "do some work"); 44 * ... 45 * // do some work 46 * ... 47 * timeLog.log(start, "MyMethod step 2", "do other work"); 48 * 49 * 50 * System.out.println ("time: " + timeLog.getCallCount()); 51 * </pre> 52 * 53 * You can configure log level in configuration file with: 54 * log4j.logger.org.codelutin.MyClass=DEBUG 55 * log4j.logger.org.codelutin.MyClass.TimeLog=INFO 56 * 57 * @author Benjamin Poussin - poussin@codelutin.com 58 * 59 * @see CallAnalyse 60 * @since 2.1 61 */ 62 public class TimeLog { 63 64 public static class CallStat { 65 66 protected long callNumber; 67 68 protected long maxCallTime = 0; 69 70 protected long minCallTime = Integer.MAX_VALUE; 71 72 protected long callTime; 73 74 @Override 75 public String toString() { 76 77 String callTimeString = StringUtil.convertTime(callTime); 78 String avgTimeString = StringUtil.convertTime(callTime / callNumber); 79 String minCallTimeString = StringUtil.convertTime(minCallTime); 80 String maxCallTimeString = StringUtil.convertTime(maxCallTime); 81 82 return String.format("total call %s, total time %s, min time %s, max time %s, avg time %s", 83 callNumber, callTimeString, minCallTimeString, maxCallTimeString, avgTimeString); 84 } 85 86 } 87 88 /** loggueur used to log time */ 89 protected Log timeLog; 90 91 /** time to trigger log time in info level (ns) (default: 1s) */ 92 protected long timeToLogInfo = 1000l * 1000000l; 93 94 /** time to trigger log time in warn level (ns) (default: 3s) */ 95 protected long timeToLogWarn = 3000l * 1000000l; 96 97 /** for each method of all proxies, keep number of call */ 98 protected Map<String, CallStat> callCount = new HashMap<String, CallStat>(); 99 100 /** @param logTime log used to log time message. */ 101 protected TimeLog(Log logTime) { 102 timeLog = logTime; 103 } 104 105 /** 106 * @param logName log category used to log time message. This category must 107 * be category used to log message in classe that use this TimeLog 108 * (normaly class name). TimeLog is added at the end. 109 */ 110 public TimeLog(String logName) { 111 this(LogFactory.getLog(logName + ".TimeLog")); 112 } 113 114 /** 115 * @param logName log category used to log time message. This category must 116 * be category used to log message in classe that use this TimeLog 117 * (normaly class name) 118 * @since 2.1 119 */ 120 public TimeLog(Class<?> logName) { 121 this(logName.getName()); 122 } 123 124 /** 125 * @param logName log category used to log time message. This category must 126 * be category used to log message in classe that use this TimeLog 127 * (normaly class name) 128 * @param timeToLogInfo time in milliseconde after that we log info 129 * @param timeToLogWarn time in milliseconde after that we log warn 130 */ 131 public TimeLog(String logName, long timeToLogInfo, long timeToLogWarn) { 132 this(logName); 133 setTimeToLogInfo(timeToLogInfo); 134 setTimeToLogWarn(timeToLogWarn); 135 } 136 137 /** 138 * @param logName log category used to log time message. This category must 139 * be category used to log message in classe that use this TimeLog 140 * (normaly class name) 141 * @param timeToLogInfo time in milliseconde after that we log info 142 * @param timeToLogWarn time in milliseconde after that we log warn 143 */ 144 public TimeLog(Class<?> logName, long timeToLogInfo, long timeToLogWarn) { 145 this(logName.getName(), timeToLogInfo, timeToLogWarn); 146 } 147 148 /** @param timeToLogInfoMs time in milliseconde after that we log info */ 149 public void setTimeToLogInfo(long timeToLogInfoMs) { 150 timeToLogInfo = timeToLogInfoMs * 1000000l; // convert ms → ns 151 } 152 153 /** @param timeToLogWarnMs time in milliseconde after that we log warn */ 154 public void setTimeToLogWarn(long timeToLogWarnMs) { 155 timeToLogWarn = timeToLogWarnMs * 1000000l; // convert ms → ns 156 } 157 158 public Map<String, CallStat> getCallCount() { 159 return callCount; 160 } 161 162 /** 163 * return time in format acceptable for 164 * {@link #log(long, long, String, String)} method. 165 * 166 * @return the current time in nanoseconds 167 */ 168 public static long getTime() { 169 return System.nanoTime(); 170 } 171 172 /** 173 * add new trace, stop time is automaticaly computed. 174 * 175 * @param startNs time returned by {@link #getTime()} method 176 * @param methodName key name to store this time 177 * @return time used as stop time, this permit to chain many add in same 178 * method to trace time. 179 */ 180 public long log(long startNs, String methodName) { 181 long result = log(startNs, getTime(), methodName, ""); 182 return result; 183 } 184 185 /** 186 * add new trace, stop time is automaticaly computed 187 * 188 * @param startNs time returned by {@link #getTime()} method 189 * @param methodName key name to store this time 190 * @param msg message to add to log 191 * @return time used as stop time, this permit to chain many add in same 192 * method to trace time. 193 */ 194 public long log(long startNs, String methodName, String msg) { 195 long result = log(startNs, getTime(), methodName, msg); 196 return result; 197 } 198 199 /** 200 * add new trace 201 * 202 * @param startNs time returned by {@link #getTime()} method 203 * @param stopNs time returned by {@link #getTime()} method 204 * @param methodName key name to store this time 205 * @param msg message to add to log 206 * @return time used as stop time (stopNs) 207 */ 208 public long log(long startNs, long stopNs, String methodName, String msg) { 209 long time = stopNs - startNs; 210 211 // incremente le nombre d'appel pour cette methode 212 CallStat calls = callCount.get(methodName); 213 if (calls == null) { 214 // is not thread safe, but if we lose one or two call, is not importante 215 calls = new CallStat(); 216 callCount.put(methodName, calls); 217 } 218 calls.callNumber++; 219 calls.callTime += time; 220 221 // keep max time 222 if (calls.maxCallTime < time) { 223 calls.maxCallTime = time; 224 } 225 226 // keep min time 227 if (calls.minCallTime > time) { 228 calls.minCallTime = time; 229 } 230 231 // affiche le temps de l'appel si necessaire 232 String timeString = StringUtil.convertTime(time); 233 String message = String.format("[%s] for method '%s', %s (%s)", 234 timeString, methodName, msg, calls); 235 236 if (time > timeToLogWarn && timeLog.isWarnEnabled()) { 237 timeLog.warn(message); 238 } else if (time > timeToLogInfo && timeLog.isInfoEnabled()) { 239 timeLog.info(message); 240 } else if (timeLog.isDebugEnabled()) { 241 timeLog.debug(message); 242 } 243 return stopNs; 244 } 245 246 }