View Javadoc
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 }