StopWatch通过打印日志记录方法耗时

我们经常会碰到这样的情况，当前端同事或者测试向你反应某个接口很慢的时候，我们就需要去排查这里面的那些代码块处理比较慢。这个时候就需要使用到打印日志的方式。
不同的包的StopWatch类方法不一样，但是都大同小异。我目前用的是springframework.util包下的。

public static void main(String[] args) {
	long start = System.currentTimeMillis();
    System.out.println("==============方法1==============");
    long end1 = System.currentTimeMillis();
    log.info("方法1耗时：" + (end1 - start) + "ms");
    System.out.println("==============方法2==============");
    long end2 = System.currentTimeMillis();
    log.info("方法2耗时：" + (end2 - end1) + "ms");
    System.out.println("==============方法3==============");
    long end3 = System.currentTimeMillis();
    log.info("方法3耗时：" + (end3 - end2) + "ms");
}

代码输出：
方法1
方法1耗时：0ms\n
方法2
方法1耗时：25ms
方法3
方法1耗时：1ms

使用StopWatch类：

public static void main(String[] args) {
        StopWatch stopWatch = new StopWatch();
        //这里可以给你的任务取一个名字，方便到时候看时间占比
        stopWatch.start("方法1");

        System.out.println("--------正在进行方法1---------");
        stopWatch.stop();
        log.info("方法1耗时:{}", stopWatch.getLastTaskTimeNanos());

        stopWatch.start("方法2");
        System.out.println("--------正在进行方法2---------");
        stopWatch.stop();
        log.info("方法2耗时:{}", stopWatch.getLastTaskTimeNanos());

        stopWatch.start("方法3");
        System.out.println("--------正在进行方法3---------");
        stopWatch.stop();
        log.info("方法3耗时:{}", stopWatch.getLastTaskTimeNanos());

        System.out.println(stopWatch.prettyPrint());
    }

输出：
--------正在进行方法1---------
16:33:48.067 [main] INFO net.spotec.mt4.task.Mt4AccountInfoAndOrderAsync - 方法1耗时:224862
--------正在进行方法2---------
16:33:48.072 [main] INFO net.spotec.mt4.task.Mt4AccountInfoAndOrderAsync - 方法2耗时:84104
--------正在进行方法3---------
16:33:48.072 [main] INFO net.spotec.mt4.task.Mt4AccountInfoAndOrderAsync - 方法3耗时:37897
StopWatch ‘’: running time = 346863 ns
<--------------------------------------------->
ns % Task name
<--------------------------------------------->
000224862 065% 方法1
000084104 024% 方法2
000037897 011% 方法3