耗时统计--StopWatch

耗时统计

在做性能优化的时候，耗时统计非常有用。
分析出时间主要消耗在哪里，才能够做出相应的优化。

System.currentTimeMillis()

平常我们在做耗时统计时，经常会用 System.currentTimeMillis()，如下：

        long start = System.currentTimeMillis();
        //其他逻辑
        long end = System.currentTimeMillis();
        System.out.println("it takes time:" + (end - start));

如果只有一个功能，那这样做还是可以的。但是如果有三四个功能，那反复地用 System.currentTimeMillis()，就会比较麻烦。
可以尝试下 StopWatch。

StopWatch 的依赖

在 apache、guava、spring的包里面，都有 StopWatch。
个人认为spring的 StopWatch比较好用些。依赖如下：

    <dependency>
        <groupId>org.springframework</groupId>
        <artifactId>spring-context</artifactId>
        <version>4.3.4.RELEASE</version>
    </dependency>

StopWatch 常用的方法

StopWatch(String id) ：构造方法，初始化
start(String taskName) ：指定任务名称，开始统计
stop():结束统计。
prettyPrint()：非常有用的方法。不仅可以统计出总的耗时，还可以显示出各个任务的耗时。
getTotalTimeMillis()：统计出总耗时。
getLastTaskName()：最后一个任务的线程名称

注意：

StopWatch在 start()之后，需要stop()之后，才能继续 start()，否则会报错：

Caused by: java.lang.IllegalStateException: Can't start StopWatch: it's already running
        at org.springframework.util.StopWatch.start(StopWatch.java:128)
        at org.springframework.util.StopWatch.start(StopWatch.java:117)

StopWatch 示例代码

import org.springframework.util.StopWatch;

public class StopWatchDemo {

    public static void main(String[] args) throws InterruptedException {
        stopWatch();
    }


    public static void stopWatch() throws InterruptedException {
        StopWatch stopWatch = new StopWatch("myStopWatch");

        stopWatch.start("任务1");
        Thread.sleep(2000);
        stopWatch.stop();

        stopWatch.start("任务2");
        Thread.sleep(1000);
        stopWatch.stop();

        //统计耗时
        System.out.println(stopWatch.prettyPrint());
    }

}

耗时统计结果如下：

StopWatch 'myStopWatch': running time (millis) = 3007
-----------------------------------------
ms     %     Task name
-----------------------------------------
02005  067%  任务1
01002  033%  任务2

多线程打印耗时

    public static void main(String[] args) {
        //实战建议使用ThreadPoolExecutor自定义线程池，避免OOM，并设置线程名称，此处是为了方便示例
        ExecutorService executor = Executors.newFixedThreadPool(10);
        StopWatch stopWatch1 = new StopWatch();
        StopWatch stopWatch2 = new StopWatch();
        //异步执行多个任务
        asyncTask(executor, stopWatch1, stopWatch2);
        //打印耗时
        printTaskTime(stopWatch1, stopWatch2);

    }

    /**
     * 异步执行多个任务
     *
     */
    private static void asyncTask(ExecutorService executor, StopWatch stopWatch1, StopWatch stopWatch2) {
        //如果不需要返回值，就用 CompletableFuture.runAsync()
        CompletableFuture<String> cf1 = CompletableFuture.supplyAsync(() -> {
            stopWatch1.start("任务1");
            sleep(1);
            stopWatch1.stop();
            return "cf1";
        }, executor);
        //第二个任务
        CompletableFuture<String> cf2 = CompletableFuture.supplyAsync(() -> {
            stopWatch2.start("任务2");
            sleep(2);
            stopWatch2.stop();
            return "cf2";
        }, executor);
        //所有任务的集合
        List<CompletableFuture<String>> futureList = new ArrayList<>();
        futureList.add(cf1);
        futureList.add(cf2);

        try {
            //所有任务的集合，2秒不出结果就超时
            CompletableFuture.allOf(futureList.toArray(new CompletableFuture[0])).get(2, TimeUnit.SECONDS);
        } catch (Exception e) {
            log.error("allOf get error.", e);
        }
    }

    /**
     * 打印耗时
     *
     */
    private static void printTaskTime(StopWatch stopWatch1, StopWatch stopWatch2) {
        BlockingQueue<StopWatch> stopWatchBlockingQueue = new LinkedBlockingQueue<>();
        stopWatchBlockingQueue.add(stopWatch1);
        stopWatchBlockingQueue.add(stopWatch2);

        StringBuilder sb = new StringBuilder("\n");
        stopWatchBlockingQueue.forEach(sw -> {
            sb.append("task ms ==>  ").append(sw.getTotalTimeMillis()).append(",taskName:").append(sw.getLastTaskName()).append("\n");
        });
        log.info(sb.toString());
    }

    public static void sleep(long time) {
        try {
            Thread.sleep(time);
        } catch (InterruptedException e) {
            log.error("sleep error.", e);
        }
    }