计时器工具 StopWatch
我是陈皮,一个在互联网 Coding 的 ITer,个人微信公众号「陈皮的JavaLib」关注第一时间阅读最新文章。
前言
平常,我们想要统计某一段代码块,或某一个方法的执行时间,最简单的是采用如下的方式。
package com.chenpi;
/**
* @author 陈皮
* @version 1.0
* @description
* @date 2022/4/2
*/
public class ChenPi {
public static void main(String[] args) throws InterruptedException {
long startTime = System.currentTimeMillis();
Thread.sleep(1000);
long endTime = System.currentTimeMillis();
System.out.println("执行耗时(ms):" + (endTime - startTime));
}
}
// 输出结果如下
执行耗时(ms):1011
但如果我们想对多个代码段进行计时,以及每个阶段计时的占比等信息,如果还是采用如上的方式就会充斥比较多的与业务无关的代码,不够简洁。
Spring StopWatch
Spring 框架有个工具类 StopWatch,它可以用来对程序中代码块,或者方法进行计时,并且支持多阶段计时,以及阶段时间占比等统计,使用起来代码比较简洁,轻量。
package com.chenpi;
import org.springframework.util.StopWatch;
/**
* @author 陈皮
* @version 1.0
* @description
* @date 2022/4/2
*/
public class ChenPi {
public static void main(String[] args) throws InterruptedException {
// 声明一个计时器
StopWatch stopWatch = new StopWatch("陈皮的计时器");
// 开始计时
stopWatch.start("发送MQ计时");
Thread.sleep(1000);
// 结束计时
stopWatch.stop();
// 打印统计
System.out.println(stopWatch.prettyPrint());
}
}
// 输出结果如下
StopWatch '陈皮的计时器': running time = 1005775500 ns
---------------------------------------------
ns % Task name
---------------------------------------------
1005775500 100% 发送MQ计时
Spring StopWatch 有以下几个常用方法:
-
StopWatch():构造一个计时器
-
StopWatch(String id):构造一个指定 id 的计时器
-
start():创建一个名为空字符串的计时任务,开始计时
-
start(String taskName):创建一个指定名称计时任务,开始计时
-
stop():结束当前任务的计时
-
getTotalTimeNanos():获取全部任务的执行时间,单位纳秒
-
getTotalTimeMillis():获取全部任务的执行时间,单位毫秒
-
shortSummary():获取简单的统计信息
-
prettyPrint():以友好方式输出总统计时间,以及各个阶段任务的执行时间
-
setKeepTaskList(boolean keepTaskList):是否在内部的列表中存储每一个任务
实践例子
当程序中有多个计时器时,可通过构造不同 id 的计时器来区分。以下演示多个不同计时器,统计不同阶段的执行时间。
package com.chenpi;
import org.springframework.util.StopWatch;
/**
* @author 陈皮
* @version 1.0
* @description
* @date 2022/4/2
*/
public class ChenPi {
public static void main(String[] args) throws InterruptedException {
m1();
m2();
}
private static void m1() throws InterruptedException {
// 声明一个计时器
StopWatch stopWatch = new StopWatch("m1计时器");
stopWatch.start("查询数据库");
Thread.sleep(1000);
stopWatch.stop();
stopWatch.start("逻辑计算");
Thread.sleep(500);
stopWatch.stop();
System.out.println(stopWatch.prettyPrint());
}
private static void m2() throws InterruptedException {
// 声明一个计时器
StopWatch stopWatch = new StopWatch("m2计时器");
stopWatch.start("远程调用");
Thread.sleep(800);
stopWatch.stop();
stopWatch.start("发送MQ");
Thread.sleep(200);
stopWatch.stop();
System.out.println(stopWatch.prettyPrint());
}
}
// 输出结果如下
StopWatch 'm1计时器': running time = 1516953200 ns
---------------------------------------------
ns % Task name
---------------------------------------------
1008091000 066% 查询数据库
508862200 034% 逻辑计算
StopWatch 'm2计时器': running time = 1013080000 ns
---------------------------------------------
ns % Task name
---------------------------------------------
809345900 080% 远程调用
203734100 020% 发生MQ
源码分析
其实 StopWatch 底层实现很简单,对于每一个任务,在任务开始和结束时刻调用System.*nanoTime*()
方法获取服务器当前的时间,然后计算每一个任务的执行时间,存储在内部。内部使用一个列表存储不同任务阶段的执行时间,最后打印输出。
package org.springframework.util;
import java.text.NumberFormat;
import java.util.ArrayList;
import java.util.List;
import java.util.concurrent.TimeUnit;
import org.springframework.lang.Nullable;
public class StopWatch {
// 计时器id
private final String id;
// 是否将任务存储到任务列表中
private boolean keepTaskList = true;
// 存储全部任务的列表
private final List<TaskInfo> taskList = new ArrayList<>(1);
// 当前任务开始时间
private long startTimeNanos;
// 当前任务名称
@Nullable
private String currentTaskName;
// 最后一个任务
@Nullable
private TaskInfo lastTaskInfo;
// 总任务数
private int taskCount;
// 总的执行时间
private long totalTimeNanos;
// 构造一个id为空字符串的计时器
public StopWatch() {
this("");
}
// 构造一个指定id的计时器
public StopWatch(String id) {
this.id = id;
}
// 获取计时器id
public String getId() {
return this.id;
}
public void setKeepTaskList(boolean keepTaskList) {
this.keepTaskList = keepTaskList;
}
// 开始计时
public void start() throws IllegalStateException {
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();
}
// 停止任务计时
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;
}
public boolean isRunning() {
return (this.currentTaskName != null);
}
@Nullable
public String currentTaskName() {
return this.currentTaskName;
}
public long getLastTaskTimeNanos() throws IllegalStateException {
if (this.lastTaskInfo == null) {
throw new IllegalStateException("No tasks run: can't get last task interval");
}
return this.lastTaskInfo.getTimeNanos();
}
public long getLastTaskTimeMillis() throws IllegalStateException {
if (this.lastTaskInfo == null) {
throw new IllegalStateException("No tasks run: can't get last task interval");
}
return this.lastTaskInfo.getTimeMillis();
}
public String getLastTaskName() throws IllegalStateException {
if (this.lastTaskInfo == null) {
throw new IllegalStateException("No tasks run: can't get last task name");
}
return this.lastTaskInfo.getTaskName();
}
public TaskInfo getLastTaskInfo() throws IllegalStateException {
if (this.lastTaskInfo == null) {
throw new IllegalStateException("No tasks run: can't get last task info");
}
return this.lastTaskInfo;
}
public long getTotalTimeNanos() {
return this.totalTimeNanos;
}
public long getTotalTimeMillis() {
return nanosToMillis(this.totalTimeNanos);
}
public double getTotalTimeSeconds() {
return nanosToSeconds(this.totalTimeNanos);
}
public int getTaskCount() {
return this.taskCount;
}
public TaskInfo[] getTaskInfo() {
if (!this.keepTaskList) {
throw new UnsupportedOperationException("Task info is not being kept!");
}
return this.taskList.toArray(new TaskInfo[0]);
}
public String shortSummary() {
return "StopWatch '" + getId() + "': running time = " + getTotalTimeNanos() + " ns";
}
public String prettyPrint() {
StringBuilder sb = new StringBuilder(shortSummary());
sb.append('\n');
if (!this.keepTaskList) {
sb.append("No task info kept");
}
else {
sb.append("---------------------------------------------\n");
sb.append("ns % Task name\n");
sb.append("---------------------------------------------\n");
NumberFormat nf = NumberFormat.getNumberInstance();
nf.setMinimumIntegerDigits(9);
nf.setGroupingUsed(false);
NumberFormat pf = NumberFormat.getPercentInstance();
pf.setMinimumIntegerDigits(3);
pf.setGroupingUsed(false);
for (TaskInfo task : getTaskInfo()) {
sb.append(nf.format(task.getTimeNanos())).append(" ");
sb.append(pf.format((double) task.getTimeNanos() / getTotalTimeNanos())).append(" ");
sb.append(task.getTaskName()).append('\n');
}
}
return sb.toString();
}
@Override
public String toString() {
StringBuilder sb = new StringBuilder(shortSummary());
if (this.keepTaskList) {
for (TaskInfo task : getTaskInfo()) {
sb.append("; [").append(task.getTaskName()).append("] took ").append(task.getTimeNanos()).append(" ns");
long percent = Math.round(100.0 * task.getTimeNanos() / getTotalTimeNanos());
sb.append(" = ").append(percent).append('%');
}
}
else {
sb.append("; no task info kept");
}
return sb.toString();
}
private static long nanosToMillis(long duration) {
return TimeUnit.NANOSECONDS.toMillis(duration);
}
private static double nanosToSeconds(long duration) {
return duration / 1_000_000_000.0;
}
// 任务实体
public static final class TaskInfo {
// 任务名称
private final String taskName;
// 任务执行时间
private final long timeNanos;
TaskInfo(String taskName, long timeNanos) {
this.taskName = taskName;
this.timeNanos = timeNanos;
}
public String getTaskName() {
return this.taskName;
}
public long getTimeNanos() {
return this.timeNanos;
}
public long getTimeMillis() {
return nanosToMillis(this.timeNanos);
}
public double getTimeSeconds() {
return nanosToSeconds(this.timeNanos);
}
}
}
StopWatch 使用起来简洁,支持多任务阶段统计,统计多任务时间占比等,统计结果直观。但是它也有不好的地方,就是一个 StopWatch 实例只能同时 start 一个 task,只能等这个 task 进行 stop 之后,才能继续 start 另一个 task。注意,StopWatch 实例不是线程安全的,也没必要进行同步处理。
lang3 StopWatch
Apache commons lang3 包下也有一个用于计时工具类 StopWatch。它还有暂停计时,恢复计时,设置分割点等功能。
org.apache.commons:commons-lang3:3.12.0
它主要有以下几个常用方法:
-
create():实例化一个计时器
-
createStarted():实例化一个计时器,并开始计时
-
StopWatch(final String message):实例化一个带有标识符的计时器
-
start():开始计时
-
split():设置分割点
-
getSplitTime():统计从 start 开始最后一个分割点的用时
-
reset():重置计时
-
suspend():暂停计时
-
resume():恢复计时
-
stop():停止计时
-
getTime():统计从 start 到当前时刻的同时
package com.chenpi;
import org.apache.commons.lang3.time.StopWatch;
/**
* @author 陈皮
* @version 1.0
* @description
* @date 2022/4/2
*/
public class ChenPi {
public static void main(String[] args) throws InterruptedException {
// 声明一个计时器
StopWatch stopWatch = new StopWatch("m1计时器");
stopWatch.start();
Thread.sleep(1000);
System.out.println("start开始到现在的时间:" + stopWatch.getTime());
stopWatch.split();
Thread.sleep(500);
System.out.println("start开始到最后一个split的时间:" + stopWatch.getSplitTime());
stopWatch.split();
Thread.sleep(500);
System.out.println("start开始到最后一个split的时间:" + stopWatch.getSplitTime());
// 重置计时
stopWatch.reset();
Thread.sleep(2000);
stopWatch.start();
Thread.sleep(1000);
System.out.println("start开始到现在的时间:" + stopWatch.getTime());
// 暂停计时
stopWatch.suspend();
Thread.sleep(3000);
// 恢复计时
stopWatch.resume();
Thread.sleep(1000);
// 结束计时
stopWatch.stop();
Thread.sleep(1000);
System.out.println("start开始到stop结束的时间:" + stopWatch.getTime());
System.out.println(stopWatch);
}
}
// 输出结果如下
start开始到现在的时间:1000
start开始到最后一个split的时间:1001
start开始到最后一个split的时间:1510
start开始到现在的时间:1004
start开始到stop结束的时间:2015
m1计时器 00:00:02.015
总结
- 如果是简单的计算执行计时,可以使用 JDK 自带的类获取系统时间进行计时。
- 如果需要多阶段计时,并且需要统计每个阶段的执行时间占比等信息,可以使用 StopWatch 工具类。
- 推荐使用 Spring StopWatch,因为本身我们项目使用 Spring 框架比较多,这样就自带了 StopWatch。
本次分享到此结束啦~~
如果觉得文章对你有帮助,点赞、收藏、关注、评论,您的支持就是我创作最大的动力!
- 点赞
- 收藏
- 关注作者
评论(0)