从零开始SpringCloud Alibaba实战（80）——如何优雅的在java中统计代码块耗时

常用写法

long start = System.currentTimeMillis();
try {
    // .... 具体的代码段
} finally {
    System.out.println("cost: " + (System.currentTimeMillis() - start));
}

使用 org.apache.commons.lang.time.StopWatch

public static void testStopWatch() throws InterruptedException {
     System.out.println("SLAMonitorThread.main() start");
     StopWatch sw = new StopWatch();
     sw.start();
     TimeUnit.SECONDS.sleep(1L);
     sw.split();
     System.out.println(
             "SLAMonitorThread.main() end. split:" + sw.getSplitTime() + ", " + sw.toSplitString());
     TimeUnit.SECONDS.sleep(1L);
     sw.split();
     System.out.println(
             "SLAMonitorThread.main() end. split:" + sw.getSplitTime() + ", " + sw.toSplitString());
     TimeUnit.SECONDS.sleep(1L);
     sw.split();
     System.out.println(
             "SLAMonitorThread.main() end. split:" + sw.getSplitTime() + ", " + sw.toSplitString());
     TimeUnit.SECONDS.sleep(1L);
     System.out.println("SLAMonitorThread.main() end. end:" + sw.getTime() + ", " + sw.toString());
 
     long start = System.currentTimeMillis();
     TimeUnit.SECONDS.sleep(1L);
     System.out.println("it consumes " + (System.currentTimeMillis() - start) + "ms");
     /*
      * SLAMonitorThread.main() start
      * SLAMonitorThread.main() end. split:1005, 0:00:01.005
      * SLAMonitorThread.main() end. split:2016, 0:00:02.016
      * SLAMonitorThread.main() end. split:3021, 0:00:03.021
      * SLAMonitorThread.main() end. end:4025, 0:00:04.025
      * it consumes 1004ms
      */
}

优点：可以多次使用，使用split即可多次使用。

缺点：需要依赖于额外的commons的jar

AOP

// 定义切点，拦截所有满足条件的方法
@Pointcut("execution(public *demo.*.*(*))")
public void point() {
}

@Around("point()")
public Object doAround(ProceedingJoinPoint joinPoint) throws Throwable {
    long start = System.currentTimeMillis();
    try{
        return joinPoint.proceed();
    } finally {
        System.out.println("cost: " + (System.currentTimeMillis() - start));
    }
}

在 Spring 的生态体系下，使用 aop 的方式来统计方法耗时，可以说少侵入且实现简单，但是有以下几个问题

统计粒度为方法级别
类内部方法调用无法生效

AutoCloseable

在 JDK1.7 引入了一个新的接口AutoCloseable, 通常它的实现类配合try{}使用，可在 IO 流的使用上，经常可以看到下面这种写法

// 读取文件内容并输出
try (Reader stream = new BufferedReader(new InputStreamReader(new FileInputStream("/tmp")))) {
    List<String> list = ((BufferedReader) stream).lines().collect(Collectors.toList());
    System.out.println(list);
} catch (IOException e) {
    e.printStackTrace();
}

注意上面的写法中，最值得关注一点是，不需要再主动的写stream.close了，主要原因就是在try(){}执行完毕之后，会调用方法AutoCloseable#close方法；

基于此，我们就会有一个想法，下一个Cost类实现AutoCloseable接口，创建时记录一个时间，close 方法中记录一个时间，并输出时间差值；将需要统计耗时的逻辑放入try(){}代码块

下面是一个具体的实现：

public static class Cost implements AutoCloseable {
    private long start;

    public Cost() {
        this.start = System.currentTimeMillis();
    }

    @Override
    public void close() {
        System.out.println("cost: " + (System.currentTimeMillis() - start));
    }
}

public static void testPrint() {
    for (int i = 0; i < 5; i++) {
        System.out.println("now " + i);
        try {
            Thread.sleep(10);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

public static void main(String[] args) {
    try (Cost c = new Cost()) {
        testPrint();
    }
    System.out.println("------over-------");
}

now 0
now 1
now 2
now 3
now 4
cost: 55
------over-------

如果代码块抛异常，也会正常输出耗时么？

public static void testPrint() {
    for (int i = 0; i < 5; i++) {
        System.out.println("now " + i);
        try {
            Thread.sleep(10);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        if (i == 3) {
            throw new RuntimeException("some exception!");
        }
    }
}

now 0
now 1
now 2
now 3
cost: 46
Exception in thread "main" java.lang.RuntimeException: some exception!
	at com.git.hui.boot.order.Application.testPrint(Application.java:43)
	at com.git.hui.boot.order.Application.main(Application.java:50)