Apache和Spring提供的StopWatch执行时间监视器

5次阅读

共计 7096 个字符,预计需要花费 18 分钟才能阅读完成。

相关阅读

【小家 java】java5 新特性(简述十大新特性)重要一跃
【小家 java】java6 新特性(简述十大新特性)鸡肋升级
【小家 java】java7 新特性(简述八大新特性)不温不火
【小家 java】java8 新特性(简述十大新特性)饱受赞誉
【小家 java】java9 新特性(简述十大新特性)褒贬不一
【小家 java】java10 新特性(简述十大新特性)小步迭代
【小家 java】java11 新特性(简述八大新特性)首个重磅 LTS 版本


前言

编码过程中我们 经常 会希望得到一段代码(一个方法)的执行时间,本文将介绍两种时间监视器(秒表)来让你优雅的、灵活的处理这个问题。

Java 源生方式

这种方式最最简单,最好理解,当然也是最为常用:我们自己书写。
例如:我们如果要统计一段代码的执行时间,经常会这么来写:

    public static void main(String[] args) {long startTime = System.currentTimeMillis();   // 获取开始时间

        // 函数主体代码
        //...

        long endTime = System.currentTimeMillis(); // 获取结束时间
        System.out.println("程序运行时间:" + (endTime - startTime) + "ms");
    }

大多数时候我们使用 ms 来表示即可,但是这么写缺乏灵活性。倘若我们要展示成纳秒、秒、甚至分钟,还得我们自己处理(把毫秒值拿来进行转换~)

当然可能到了 JDK8 以后,我们这么做能变得稍微灵活一些:可以这么处理:

    public static void main(String[] args) {Instant start = Instant.now();
        //doSomething();
        Instant end = Instant.now();

        Duration duration = Duration.between(start, end);
        System.out.println("millis =" + duration.toMillis());
    }

这个比上面灵活度强一些。但也还是有一定的缺点:步骤稍显复杂,总体上还是不够优雅,也不是那么的灵活。
那么本文针对此问题介绍一个工具:StopWatch执行时间监视器。借助它来统计我们程序的执行时间,带给非常多的方便和优雅。

StopWatch需要依赖额外的 Jar:commons-lang3或者spring-core,但因这两个 Jar 是 Java 开发中都必导的,因此依赖兼容性方面可以忽略

StopWatch有很多开源的框架都有提供类似的功能:比如 Apache 的 commons-lang3,当然还有Spring framwork 自己提供的,本文将针对此俩分别做介绍~

Commons-lang3 的 StopWatch

Apache提供的这个任务执行监视器功能丰富强大(比 Spring 的强大),灵活性强,如下经典实用案例:

    public static void main(String[] args) throws Exception {StopWatch watch = StopWatch.createStarted(); // 创建后立即 start,常用
        //StopWatch watch = new StopWatch();
        //watch.start();

        Thread.sleep(1000);
        System.out.println("统计从开始到现在运行时间:" + watch.getTime() + "ms"); //1000ms

        Thread.sleep(1000);
        watch.split();
        System.out.println("从 start 到此刻为止的时间:" + watch.getTime());
        System.out.println("从开始到第一个切入点运行时间:" + watch.getSplitTime()); //2245

        Thread.sleep(1000);
        watch.split();
        System.out.println("从开始到第二个切入点运行时间:" + watch.getSplitTime());

        watch.reset(); // 重置后必须使用 start 方法
        watch.start();
        Thread.sleep(1000);
        System.out.println("重新开始后到当前运行时间是:" + watch.getTime()); //1000

        watch.suspend(); // 暂停
        Thread.sleep(6000); // 模拟暂停 6 秒钟

        watch.resume(); // 上面 suspend,这里要想重新统计,需要恢复一下
        System.out.println("恢复后执行的时间是:" + watch.getTime()); //1000  注意此时这个值还是 1000

        watch.stop();
        System.out.println("花费的时间》》" + watch.getTime() + "ms"); //1002ms
        System.out.println("花费的时间》》" + watch.getTime(TimeUnit.SECONDS) + "s"); //1s 可以直接转成 s

    }

打印结果:

统计从开始到现在运行时间:1007ms
从 start 到此刻为止的时间:2008
从开始到第一个切入点运行时间:2008
从开始到第二个切入点运行时间:3009
重新开始后到当前运行时间是:1000
恢复后执行的时间是:1000
花费的时间》》1001ms
花费的时间》》1s

如上就是 StopWatch 的基本使用方法,足以见到了它的强大吧,当然使用起来复杂度也是提升了些的。

核心原理解释

原理相对简单,简单看看源码便知:

// @since 2.0
public class StopWatch {
    // @since 3.5  这个静态方法出现得稍微晚点哦~
    public static StopWatch createStarted() {final StopWatch sw = new StopWatch();
        sw.start();
        return sw;
    }

    // 这些成员变量是实现的核心~~~~~~~~~~~~~~
    private State runningState = State.UNSTARTED;
    private SplitState splitState = SplitState.UNSPLIT;
    private long startTime;
    // 思考:为何有了 nonaTime 这里还得记录一个 Millis Time 呢???// 因为 nanoTime 只能拿来计算差值(耗时)但是 getStartTime()这个老 API 还得靠 MillsTime~~~
    private long startTimeMillis;
    private long stopTime;
    
    // 可见:start 方法可不是能够多次调用的哦~~ 和状态是有关的
    public void start() {if (this.runningState == State.STOPPED) {throw new IllegalStateException("Stopwatch must be reset before being restarted.");
        }
        if (this.runningState != State.UNSTARTED) {throw new IllegalStateException("Stopwatch already started.");
        }
        this.startTime = System.nanoTime();
        this.startTimeMillis = System.currentTimeMillis();
        this.runningState = State.RUNNING;
    }

    // 停表时,最重要的是记录下了 stopTime 的值~~~ 然后标记状态
    public void stop() {if (this.runningState != State.RUNNING && this.runningState != State.SUSPENDED) {throw new IllegalStateException("Stopwatch is not running.");
        }
        if (this.runningState == State.RUNNING) {this.stopTime = System.nanoTime();
        }
        this.runningState = State.STOPPED;
    }

    // 状态变为非开始状态...
    public void reset() {
        this.runningState = State.UNSTARTED;
        this.splitState = SplitState.UNSPLIT;
    }

    // 暂停:stopTime 也给了一个值
    public void suspend() {if (this.runningState != State.RUNNING) {throw new IllegalStateException("Stopwatch must be running to suspend.");
        }
        this.stopTime = System.nanoTime();
        this.runningState = State.SUSPENDED;
    }

    // 这两个方法是获取差值的
    public long getTime() {return getNanoTime() / NANO_2_MILLIS;
    }
    // @since 3.5
    public long getTime(final TimeUnit timeUnit) {return timeUnit.convert(getNanoTime(), TimeUnit.NANOSECONDS);
    }

    // @since 2.4 老 API  这叫获取启动的时间(啥时候启动的)public long getStartTime() {if (this.runningState == State.UNSTARTED) {throw new IllegalStateException("Stopwatch has not been started");
        }
        // System.nanoTime is for elapsed time
        return this.startTimeMillis;
    }
}

可以看到原理是很简单的,无非就是包装了暂停、回复、split 等功能嘛

使用细节

==getTimegetSplitTime 有啥区别呢?==
为了说明问题,此处我们看看 getNanoTime()getSplitNanoTime()亦可:

    public long getNanoTime() {if (this.runningState == State.STOPPED || this.runningState == State.SUSPENDED) {return this.stopTime - this.startTime;} else if (this.runningState == State.UNSTARTED) {return 0;} else if (this.runningState == State.RUNNING) {return System.nanoTime() - this.startTime;
        }
        throw new RuntimeException("Illegal running state has occurred.");
    }

     public long getSplitNanoTime() {if (this.splitState != SplitState.SPLIT) {throw new IllegalStateException("Stopwatch must be split to get the split time.");
        }
        return this.stopTime - this.startTime;
    }

我们发现:

  • 调用 getSplit... 相关方法前,必须先调用 Split 方法

spilit()方法源码如下:

    public void split() {if (this.runningState != State.RUNNING) {throw new IllegalStateException("Stopwatch is not running.");
        }
        this.stopTime = System.nanoTime();
        this.splitState = SplitState.SPLIT;
    }

在调用 split 方法后,watch的状态改为了 SPLIT 且,且,且 stopTime 设置为了当前时间 。因此此处我们的stopTime 停止了,这个时候调用 getSplitNanoTime(),返回的是 start 到 split 那时的时间差值。因此用此方法可以 插入先停止 stopTime()(有点插队的赶脚),最后 再输出(先插好队,最后在输出)~

getTime() 就是拿当前的时间戳,减去 startTime,一般不涉及到stopTime 的值,因此 splitTime 处理计算时间显然 更加的灵活 ,但是,一般我们使用getTime() 就足够了

Spring 的 StopWatch

Spring提供的这个任务监视器,我还是蛮喜欢使用的,因为一个它能够帮我同事监控多个任务,使用起来也很方便。先看一个简单的使用案例:

注意:一个监视器能够记录多个任务的执行时间这个特点非常重要哦~
比如:我们可以记录 多段代码耗时时间,然后一次性打印~

    public static void main(String[] args) throws Exception {
        // 强烈每一个秒表都给一个 id,这样查看日志起来能够更加的精确
        // 至于 Id 我觉得给 UUID 是可行的~
        StopWatch sw = new StopWatch(UUID.randomUUID().toString());

        sw.start("起床");
        Thread.sleep(1000);
        System.out.println("当前任务名称:" + sw.currentTaskName());
        sw.stop();

        sw.start("洗漱");
        Thread.sleep(2000);
        System.out.println("当前任务名称:" + sw.currentTaskName());
        sw.stop();

        sw.start("锁门");
        Thread.sleep(500);
        System.out.println("当前任务名称:" + sw.currentTaskName());
        sw.stop();

        System.out.println(sw.prettyPrint()); // 这个方法打印在我们记录日志时是非常友好的  还有百分比的分析哦
        System.out.println(sw.shortSummary());
        System.out.println(sw.currentTaskName()); // stop 后它的值为 null


        // 最后一个任务的相关信息
        System.out.println(sw.getLastTaskName());
        System.out.println(sw.getLastTaskInfo());

        // 任务总的耗时  如果你想获取到每个任务详情(包括它的任务名、耗时等等)可使用
        System.out.println("所有任务总耗时:" + sw.getTotalTimeMillis());
        System.out.println("任务总数:" + sw.getTaskCount());
        System.out.println("所有任务详情:" + sw.getTaskInfo()); // 拿到所有的任务
    }

打印:

当前任务名称:起床
当前任务名称:洗漱
当前任务名称:锁门
StopWatch 'd6ba9412-d551-4ba7-8b0e-1b7ccb42855d': running time (millis) = 3504
-----------------------------------------
ms     %     Task name
-----------------------------------------
01001  029%  起床
02000  057%  洗漱
00503  014%  锁门

StopWatch 'd6ba9412-d551-4ba7-8b0e-1b7ccb42855d': running time (millis) = 3504
null
锁门
org.springframework.util.StopWatch$TaskInfo@2d554825
所有任务总耗时:3504
任务总数:3
所有任务详情:[Lorg.springframework.util.StopWatch$TaskInfo;@68837a77

我个人偏爱使用 Spring 提供的这个监视器,是因为它提供的 prettyPrint() 打印在日志里进行分析可以非常的直观,并且我觉得提供的多任务支持也更加实用一点,当然仅仅个人偏好而已~

最后

很多时候,写代码也是一种艺术,而借助这种实用工具我就觉得艺术感更强些。希望我们能有追求更加美好事物的心,这点对于接纳新知识特别重要。此处推荐这个监视器来代替之前的的使用,能让小伙伴们更加灵活的分析你的代码~

知识交流

若文章格式混乱,可点击:原文链接 - 原文链接 - 原文链接 - 原文链接 - 原文链接

==The last:如果觉得本文对你有帮助,不妨点个赞呗。当然分享到你的朋友圈让更多小伙伴看到也是被 作者本人许可的~==

** 若对技术内容感兴趣可以加入 wx 群交流:Java 高工、架构师 3 群
若群二维码失效,请加 wx 号:fsx641385712(或者扫描下方 wx 二维码)。并且备注:"java 入群" 字样,会手动邀请入群 **

正文完
 0