JAVA方法耗时信息捕捉并日志

一. 设计思想：

               1、要保证日志的先后顺序，要保证输出的先后顺序；

               2、其次就是要保证不要出现存储耗时时间的List量太大的情况，所以解决方法是

                              A、使用ThreadLocal，每个线程输出自己的日志，这样比较清晰；

                              B、要做一下MAX_SIZE控制

               3、要做到灵活控制开关，本方法是用了日志的DEBUG级别进行开关控制，当DEBUG时，统计方法耗时信息，不影响线上数据

               4、方法API简单，直接使用record和print方法即可。

二. 使用场合：仅限于单次线程中进行的方法时间捕捉

三. 代码实现：

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import java.text.SimpleDateFormat;
import java.util.*;

/**
* 记录方法执行的时间
* @author wull
*/
public class MethodTimeUtil {
/** LOGGER */
private static final Logger log = LoggerFactory.getLogger(MethodTimeUtil.class);
/** ThreadLocal缓存 */
private static ThreadLocal<LinkedHashMap<String,MethodTime>> mts = new ThreadLocal<LinkedHashMap<String,MethodTime>>();
/** 前缀 */
private static final String PREFIX = "------->方法执行时间记录 ";
/** 根据日志级别，来开启本功能 */
private static boolean isDebug = log.isDebugEnabled() ;
/** 存入list的最大数 */
private static int MAX_SIZE = 1000;
/** 输出时间的格式 */
private static final SimpleDateFormat TIME_FORMAT = new SimpleDateFormat("hh:MM:ss");

/**
* 录入时间数据
* @param title
* @param isStart
*/
public static void record(String title ,boolean isStart){
if(isDebug == false){
return ;
}
LinkedHashMap<String,MethodTime> map = mts.get();
if(map == null){
map = new LinkedHashMap<String,MethodTime>();
}

if(map.size() > MAX_SIZE){
printByParam(false);
}

if(isStart){
map.put(title, new MethodTime(title, isStart));
}else{
MethodTime mt = map.get(title);
if(mt != null && mt.getTitle().equals(title)){
mt.setStart(false);
mt.setTime(System.currentTimeMillis() - mt.getTime());
}else{
map.put(title, new MethodTime(title, isStart));
}
}
mts.set(map);
}

/**
* hide
* 打印已经录入的数据，并按照条件清空这些数据
*/
private static void printByParam(boolean isFinal){
String preLog = PREFIX + " THREAD["+Thread.currentThread().getName() +"] ";
if(isDebug == false){
return ;
}
LinkedHashMap<String,MethodTime> map = mts.get();
if(map == null || map.size() == 0){
log.debug( preLog + "当前线程没有记录方法时间信息。");
return ;
}

int listInitSize = map.size();
Iterator iterator = map.entrySet().iterator();
while(iterator.hasNext()){
Map.Entry<String, MethodTime> entry = (Map.Entry<String, MethodTime>)iterator.next();
MethodTime mt = entry.getValue();
if (mt.isStart() == false){
log.debug( preLog + mt.getTitle()+"------------>method last:"+mt.getTime()+" MillisSecords");
iterator.remove();
}else{
if(isFinal) {
log.debug(preLog + mt.getTitle() + "------------->method startTime:" + TIME_FORMAT.format(new Date(mt.getTime())));
}
}
}

// 如果清理了已经获知时间的时间信息后，仍然大于MAX_SIZE,那就清理所有
if(isFinal) {
log.debug( preLog +"print finish,recodList.size=" + listInitSize );
map.clear();
}
}

/**
* open
* 打印已经录入的数据，并清空这些数据
*/
public static void print(){
printByParam(true);
}

public static void main(String [] arggs){

MethodTimeUtil.record("测试1：",true);
MethodTimeUtil.record("测试2：",true);
MethodTimeUtil.record("测试1：",false);
MethodTimeUtil.record("测试2：",false);
MethodTimeUtil.print();

for(int k= 1;k<5;k++) {
new Thread("Thread-" + k) {
public void run() {
Random r = new Random();
for (int i = 1; i <= 5; i++) {
int titleNo = i;
String title = titleNo + ".TEST:";
boolean b = true;
MethodTimeUtil.record(title, b);
}
MethodTimeUtil.print();
}
}.start();
}
}
}

class MethodTime {
private String title;
private boolean isStart;
private long time;
public MethodTime(String title, boolean isStart) {
this.title = title;
this.isStart = isStart;
this.time = System.currentTimeMillis();
}

public String getTitle() {
return title;
}
public void setTitle(String title) {
this.title = title;
}
public boolean isStart() {
return isStart;
}
public void setStart(boolean isStart) {
this.isStart = isStart;
}
public long getTime() {
return time;
}
public void setTime(long time) {
this.time = time;
}
}


四. 结果输出：
Connected to the target VM, address: '127.0.0.1:58681', transport: 'socket'
16:52:34.618 [main] DEBUG n.x.teacheval.utils.MethodTimeUtil - ------->方法执行时间记录 THREAD[main] 测试1：------------>method last:0 MillisSecords
16:52:34.623 [main] DEBUG n.x.teacheval.utils.MethodTimeUtil - ------->方法执行时间记录 THREAD[main] 测试2：------------>method last:0 MillisSecords
16:52:34.624 [main] DEBUG n.x.teacheval.utils.MethodTimeUtil - ------->方法执行时间记录 THREAD[main] print finish,recodList.size=2
16:52:34.625 [Thread-1] DEBUG n.x.teacheval.utils.MethodTimeUtil - ------->方法执行时间记录 THREAD[Thread-1] 1.TEST:------------->method startTime:04:11:34
16:52:34.625 [Thread-1] DEBUG n.x.teacheval.utils.MethodTimeUtil - ------->方法执行时间记录 THREAD[Thread-1] 2.TEST:------------->method startTime:04:11:34
16:52:34.625 [Thread-1] DEBUG n.x.teacheval.utils.MethodTimeUtil - ------->方法执行时间记录 THREAD[Thread-1] 3.TEST:------------->method startTime:04:11:34
16:52:34.625 [Thread-1] DEBUG n.x.teacheval.utils.MethodTimeUtil - ------->方法执行时间记录 THREAD[Thread-1] 4.TEST:------------->method startTime:04:11:34
16:52:34.625 [Thread-1] DEBUG n.x.teacheval.utils.MethodTimeUtil - ------->方法执行时间记录 THREAD[Thread-1] 5.TEST:------------->method startTime:04:11:34
16:52:34.625 [Thread-1] DEBUG n.x.teacheval.utils.MethodTimeUtil - ------->方法执行时间记录 THREAD[Thread-1] print finish,recodList.size=5
16:52:34.626 [Thread-3] DEBUG n.x.teacheval.utils.MethodTimeUtil - ------->方法执行时间记录 THREAD[Thread-3] 1.TEST:------------->method startTime:04:11:34
16:52:34.626 [Thread-3] DEBUG n.x.teacheval.utils.MethodTimeUtil - ------->方法执行时间记录 THREAD[Thread-3] 2.TEST:------------->method startTime:04:11:34
16:52:34.626 [Thread-3] DEBUG n.x.teacheval.utils.MethodTimeUtil - ------->方法执行时间记录 THREAD[Thread-3] 3.TEST:------------->method startTime:04:11:34
16:52:34.626 [Thread-2] DEBUG n.x.teacheval.utils.MethodTimeUtil - ------->方法执行时间记录 THREAD[Thread-2] 1.TEST:------------->method startTime:04:11:34
16:52:34.626 [Thread-3] DEBUG n.x.teacheval.utils.MethodTimeUtil - ------->方法执行时间记录 THREAD[Thread-3] 4.TEST:------------->method startTime:04:11:34
16:52:34.626 [Thread-2] DEBUG n.x.teacheval.utils.MethodTimeUtil - ------->方法执行时间记录 THREAD[Thread-2] 2.TEST:------------->method startTime:04:11:34
16:52:34.626 [Thread-3] DEBUG n.x.teacheval.utils.MethodTimeUtil - ------->方法执行时间记录 THREAD[Thread-3] 5.TEST:------------->method startTime:04:11:34
16:52:34.626 [Thread-2] DEBUG n.x.teacheval.utils.MethodTimeUtil - ------->方法执行时间记录 THREAD[Thread-2] 3.TEST:------------->method startTime:04:11:34
16:52:34.626 [Thread-3] DEBUG n.x.teacheval.utils.MethodTimeUtil - ------->方法执行时间记录 THREAD[Thread-3] print finish,recodList.size=5
16:52:34.626 [Thread-2] DEBUG n.x.teacheval.utils.MethodTimeUtil - ------->方法执行时间记录 THREAD[Thread-2] 4.TEST:------------->method startTime:04:11:34
16:52:34.626 [Thread-2] DEBUG n.x.teacheval.utils.MethodTimeUtil - ------->方法执行时间记录 THREAD[Thread-2] 5.TEST:------------->method startTime:04:11:34
16:52:34.626 [Thread-2] DEBUG n.x.teacheval.utils.MethodTimeUtil - ------->方法执行时间记录 THREAD[Thread-2] print finish,recodList.size=5
16:52:34.636 [Thread-4] DEBUG n.x.teacheval.utils.MethodTimeUtil - ------->方法执行时间记录 THREAD[Thread-4] 1.TEST:------------->method startTime:04:11:34
16:52:34.636 [Thread-4] DEBUG n.x.teacheval.utils.MethodTimeUtil - ------->方法执行时间记录 THREAD[Thread-4] 2.TEST:------------->method startTime:04:11:34
16:52:34.636 [Thread-4] DEBUG n.x.teacheval.utils.MethodTimeUtil - ------->方法执行时间记录 THREAD[Thread-4] 3.TEST:------------->method startTime:04:11:34
16:52:34.636 [Thread-4] DEBUG n.x.teacheval.utils.MethodTimeUtil - ------->方法执行时间记录 THREAD[Thread-4] 4.TEST:------------->method startTime:04:11:34
16:52:34.636 [Thread-4] DEBUG n.x.teacheval.utils.MethodTimeUtil - ------->方法执行时间记录 THREAD[Thread-4] 5.TEST:------------->method startTime:04:11:34
16:52:34.637 [Thread-4] DEBUG n.x.teacheval.utils.MethodTimeUtil - ------->方法执行时间记录 THREAD[Thread-4] print finish,recodList.size=5
Disconnected from the target VM, address: '127.0.0.1:58681', transport: 'socket'

Process finished with exit code 0