在实践过程中，我们经常需要记录一个任务执行的耗时，这是评价代码好坏，评测代码性能，排查业务执行问题的重要操作。那么，你是如何来获取并计算任务执行耗时的呢?通过new Date获得时间进行换算?还是有更好的方案?本文给你答案。
获取任务耗时通常做法
获取任务耗时，最简单的方式就是打印当前时间与任务开始执行时间的差值，实例代码如下：
- @Test
- public void testElapsedTimes() throws InterruptedException {
- long startTime = new Date().getTime();
- // do something
- Thread.sleep(1000);
- System.out.println("执行耗时：" + (new Date().getTime() - startTime) + "ms");
- }
上述方式实现简单，逻辑也比较直观。但如果执行大量测试，测试中还有不同的代码逻辑块，那么需要改动的地方就比较多。
改进做法
在上述代码中，如果IDE安装有代码检查工具，则会提示采用System.currentTimeMillis()来获取时间，而不是new Date().getTime()的方式。
改造之后，实现代码如下：
- @Test
- public void testElapsedTimes1() throws InterruptedException {
- long startTime = System.currentTimeMillis();
- // do something
- Thread.sleep(1000);
- System.out.println("执行耗时：" + (System.currentTimeMillis() - startTime) + "ms");
- }
在这样的场景下(无需获取更多Date相关信息)也推荐使用System.currentTimeMillis()来获取时间戳。至于为什么，看一下Date的源码实现就知道了。
Date的构造方法：
- public Date() {
- this(System.currentTimeMillis());
- }
Date在构造时，本质上也是先获得了System.currentTimeMillis()，然后再初始化其他信息。既然我们只需要时间戳，那就没必要再构建Date对象了。从性能层面来说，能优化则优化。
Spring的StopWatch
上述两种方式虽然性能和写法有所区别，但本质是一样的。下面我们来讲讲Spring提供的StopWatch类，它不仅可实现上述功能，而且还可以做类似任务执行时间控制，也就是封装了一个对开始时间、结束时间记录操作的Java类。
先通过StopWatch类来实现一下上述功能：
- @Test
- public void testStopWatch() throws InterruptedException {
- StopWatch sw = new StopWatch();
- sw.start("开始执行业务");
- // do something
- Thread.sleep(1000);
- sw.stop();
- System.out.println(sw.getTotalTimeMillis());
- }
通过创建StopWatch对象，然后调用它的start、stop方法来区分执行任务区间，通过getTotalTimeMillis()方法获得总耗时。
乍一看，代码好像还比之前的方式多了，体现不出来什么优势啊!下面我们再来看一个复杂点的示例：
- @Test
- ublic void testStopWatch1() throws InterruptedException {
- StopWatch sw = new StopWatch();
- sw.start("起床");
- Thread.sleep(1000);
- sw.stop();
- sw.start("洗漱");
- Thread.sleep(2000);
- sw.stop();
- sw.start("锁门");
- Thread.sleep(500);
- sw.stop();
- System.out.println(sw.prettyPrint());
- System.out.println(sw.getTotalTimeMillis());
- System.out.println(sw.getLastTaskName());
- System.out.println(sw.getLastTaskInfo());
- System.out.println(sw.getTaskCount());
执行上述测试示例，打印结果如下：
- StopWatch '': running time = 3509166972 ns
- ---------------------------------------------
- ns % Task name
- ---------------------------------------------
- 1003330360 029% 起床
- 2001421734 057% 洗漱
- 504414878 014% 锁门
- 3509
- 锁门
- org.springframework.util.StopWatch$TaskInfo@12f40c25
- 3
此时，看到StopWatch的魅力所在了吗?
- 通过多组start、stop方法，将业务代码块进行区分，可获得不同代码块的执行耗时;
- 可以通过start方法传入taskName，对每个代码块进行命名;
- 可以对总任务耗时、每个任务耗时进行统计分析;
- prettyPrint()方法，可以优雅的打印出统计分析信息;
- getTotalTimeMillis()方法，打印出总耗时;
- getLastTaskName()方法，打印最后一个任务名称;
- getLastTaskInfo()方法，获得最后一个任务的TaskInfo，进而获得更多相关信息;
- getTaskCount()方法，获得任务数;
现在再看，使用StopWatch是不是可以获得更多有用的信息?
StopWatch的实现原理
最后呢，我们再来看一眼源码，了解一下StopWatch的实现机制。
先看StopWatch的start方法实现：
- public void start(String taskName) throws IllegalStateException {
- if (this.currentTaskName != null) {
- throw new IllegalStateException("Can't start StopWatch: it's already running");
- }
- this.currentTaskName = taskName;
- this.startTimeNanos = System.nanoTime();
- }
start方法中记录了任务名称和任务执行的时间，基于System.nanoTime()获得。
stop方法实现如下：
- public void stop() throws IllegalStateException {
- if (this.currentTaskName == null) {
- throw new IllegalStateException("Can't stop StopWatch: it's not running");
- }
- long lastTime = System.nanoTime() - this.startTimeNanos;
- this.totalTimeNanos += lastTime;
- this.lastTaskInfo = new TaskInfo(this.currentTaskName, lastTime);
- if (this.keepTaskList) {
- this.taskList.add(this.lastTaskInfo);
- }
- ++this.taskCount;
- this.currentTaskName = null;
- }
在stop方法中，通过两个时间戳相减获得lastTime，也就是一个任务的执行时间;lastTime累计相加获得总的执行时间;同时，记录任务列表、任务数统计。
而其他get方法，则是对start、stop中获取的数据的进一步统计、分析、格式化输出而已。
小结
有些功能当我们使用习惯了，可能就固守于一个实现方式，但如果去参考学习其他框架中类似功能的实现，往往会有些新的突破。如果你在使用Spring的框架，建议你尝试一下StopWatch这个API，可以让你的时间统计日志更加高端大气。
