io.ultreia.java4all.util.TimeLog Maven / Gradle / Ivy
Show all versions of java-util Show documentation
package io.ultreia.java4all.util;
/*-
* #%L
* Java Util extends by Ultreia.io
* %%
* Copyright (C) 2018 - 2021 Ultreia.io
* %%
* 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
* .
* #L%
*/
import io.ultreia.java4all.lang.Strings;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import java.util.HashMap;
import java.util.Map;
/**
* Cette classe permet de facilement trace le temps d'execution entre deux points
*
* usage
*
* final private static final 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());
*
*
* You can configure log level in configuration file with:
* log4j.logger.org.yo.MyClass=DEBUG
* log4j.logger.org.yo.MyClass.TimeLog=INFO
*
* @author Benjamin Poussin - [email protected]
* @author Tony Chemit - [email protected]
* @see CallAnalyse
* Created on 10/06/2021.
* @since 1.0.12
*/
public class TimeLog {
/**
* Log used to log time
*/
protected Logger 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 callCount = new HashMap<>();
public static class CallStat {
protected long callNumber;
protected long maxCallTime = 0;
protected long minCallTime = Integer.MAX_VALUE;
protected long callTime;
@Override
public String toString() {
String callTimeString = Strings.convertTime(callTime);
String avgTimeString = Strings.convertTime(callTime / callNumber);
String minCallTimeString = Strings.convertTime(minCallTime);
String maxCallTimeString = Strings.convertTime(maxCallTime);
return String.format("total call %s, total time %s, min time %s, max time %s, avg time %s",
callNumber, callTimeString, minCallTimeString, maxCallTimeString, avgTimeString);
}
}
/**
* return time in format acceptable for
* {@link #log(long, long, String, String)} method.
*
* @return the current time in nanoseconds
*/
public static long getTime() {
return System.nanoTime();
}
/**
* @param logTime log used to log time message.
*/
public TimeLog(Logger logTime) {
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
* (normally class name). TimeLog is added at the end.
*/
public TimeLog(String logName) {
this(LogManager.getLogger(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
* (normally 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
* (normally class name)
* @param timeToLogInfo time in milliseconde after that we log info
* @param timeToLogWarn time in milliseconde after that we log warn
*/
public TimeLog(Logger 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
* (normally 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
* (normally 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) {
timeToLogInfo = timeToLogInfoMs * 1000000L; // convert ms → ns
}
/**
* @param timeToLogWarnMs time in milliseconde after that we log warn
*/
public void setTimeToLogWarn(long timeToLogWarnMs) {
timeToLogWarn = timeToLogWarnMs * 1000000L; // convert ms → ns
}
public Map getCallCount() {
return callCount;
}
/**
* add new trace, stop time is automatically computed.
*
* @param startNs time returned by {@link #getTime()} method
* @param methodName key name to store this time
* @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) {
return log(startNs, getTime(), methodName, "");
}
/**
* add new trace, stop time is automatically 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) {
return log(startNs, getTime(), methodName, msg);
}
/**
* 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;
// increments call count for this 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;
// keep max time
if (calls.maxCallTime < time) {
calls.maxCallTime = time;
}
// keep min time
if (calls.minCallTime > time) {
calls.minCallTime = time;
}
// log message if necessary
String timeString = Strings.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;
}
}