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 }