Together for a Shared future
源码解读
最近项目有个耗时API，于是想办法定位分析慢的地方和原因，我第一时间想到了打log，但是胡乱打日志，不能有效帮我分析问题；此时，同事推荐了一个很有用的工具 -- StopWatch。
StopWatch介绍
常见的秒表工具类有几种：
- org.springframework.util.StopWatch
- org.apache.commons.lang.time.StopWatch
- guava的秒表StopWatch
这里重点介绍下 org.springframework.util.StopWatch的用法。springframework的Stopwatch类提供了一种方便的机制来测量运行时间，它使用了操作系统和硬件提供的最高分辨率机制，通常少于1毫秒（相比之下DateTime.Now和Environment.TickCount的分辨率在15毫秒左右）。
应用案例
@Controller
@RequestMapping("/app")
@Slf4j
public class TestController extends BaseController{
@Autowired
private SystemService systemService;
@RequestMapping("/test")
@ResponseBody
public String testDemo() throws Exception {
StopWatch clock = new StopWatch("stop watch test");
clock.start("test1");
systemService.step1();
clock.stop();
clock.start("test1");
systemService.step2();
clock.stop();
clock.start("test3");
systemService.step3();
clock.stop();
Thread.sleep(1000);
log.debug(MessageFormat.format("log:{0}", clock.prettyPrint()));
return "Hello World!";
}
}
StopWatch '': running time = 12292625 ns
---------------------------------------------
ns % Task name
---------------------------------------------
012145833 099% test1
000101042 001% test2
000045750 000% test3
源码分析
以上面的demo为例子，我们逐步分析StopWatch的源码，一共有4个步骤：
- new StopWatch();
- clock.start("test1");
- clock.stop();
- clock.prettyPrint();
1、新建StopWatch对象
源码：
/**
* Construct a new {@code StopWatch}.
* <p>Does not start any task.
*/
public StopWatch() {
this("");
}
/**
* Construct a new {@code StopWatch} with the given ID.
* <p>The ID is handy when we have output from multiple stop watches and need
* to distinguish between them.
* <p>Does not start any task.
* @param id identifier for this stop watch
*/
public StopWatch(String id) {
this.id = id;
}
分析：
两个重载的构造器，我们可以手动设置计时器的名称，如果没有则默认为空字符串。
2、计时器-start
源码：
/**
* Start a named task.
* <p>The results are undefined if {@link #stop()} or timing methods are
* called without invoking this method first.
* @param taskName the name of the task to start
* @see #start()
* @see #stop()
*/
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();
}
分析：
- 判断当前的计时任务是否停止：用的是一个乐观锁（currentTaskName 标志了 计时器 是否正在被某个任务占用）
- currentTaskName 不为空：正在被某个任务占用，抛出异常
- currentTaskName 为空：计时器重新计时
- 设置当前任务名称 currentTaskName
- 设置任务开始时间 startTimeNanos：使用了 System.nanoTime() 来测量每个Task耗时
注意：
System.nanoTime()返回的并不是当前时间（和System.currentTimeMillis()的含义不一样），而是当前时刻到一个固定但是可以任意的时间点的差值（是不是有点绕😜，为了表述的严谨只能如此)，也就是说返回值可能是正数也可能是负数。
但实际中的实现一般是当前时刻到过去的某个时间点（比如Linux用的系统启动时间点）的差值；所以只能用若干System.nanoTime()调用获取其差值做一些判断或运算，换而言之一次调用基本是没有意义的；
而且不同Java虚拟机调用System.nanoTime()用的起始点可能是不一样的，也就是说不同虚拟机之间不能用其值来判断时间流逝。
https://coderdeepwater.cn/2021/01/05/java_source_code/nanoTime/
3、计时器-stop
源码：
/**
* Stop the current task.
* <p>The results are undefined if timing methods are called without invoking
* at least one pair of {@code start()} / {@code stop()} methods.
* @see #start()
* @see #start(String)
*/
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;
}
// TaskInfo 静态内部类（多实例共享一个 TaskInfo 对象）
public static final class TaskInfo {
private final String taskName;
private final long timeNanos;
TaskInfo(String taskName, long timeNanos) {
this.taskName = taskName;
this.timeNanos = timeNanos;
}
/**
* Get the name of this task.
*/
public String getTaskName() {
return this.taskName;
}
/**
* Get the time in nanoseconds this task took.
* @since 5.2
* @see #getTimeMillis()
* @see #getTimeSeconds()
*/
public long getTimeNanos() {
return this.timeNanos;
}
/**
* Get the time in milliseconds this task took.
* @see #getTimeNanos()
* @see #getTimeSeconds()
*/
public long getTimeMillis() {
return nanosToMillis(this.timeNanos);
}
/**
* Get the time in seconds this task took.
* @see #getTimeMillis()
* @see #getTimeNanos()
*/
public double getTimeSeconds() {
return nanosToSeconds(this.timeNanos);
}
}
分析：
- currentTaskName：乐观锁
- currentTaskName 为空：没有进行中的测量Task，抛异常
- currentTaskName 不为空：有进行中的Task
- 计算 lastTime ：System.nanoTime() - this.startTimeNanos;
- 计算 totalTimeNanos：this.totalTimeNanos += lastTime;
- 结束任务，构造测量结果，塞到任务列表里
- 构造 TaskInfo 对象
- 判断是否拓展 taskList 集合
- yes：放到 taskList 集合
- no：跳过，放弃该次任务收集
- 释放乐观锁：currentTaskName 置 null
4、计时器-结果输出
源码：
/**
* Generate a string with a table describing all tasks performed.
* <p>For custom reporting, call {@link #getTaskInfo()} and use the task info
* directly.
*/
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();
}
分析：
- 结果就是 StringBuilder 拼装
以上就是demo的源码解析，确实是挺简单的一个工具类。
StopWatch的其他能力
下面是StopWatch的方法列表：
不足
StopWatch对象不是设计为线程安全的，并且不使用同步。一般是在开发过程中验证性能，而不是作为生产应用程序的一部分。
总结
上面是spring-framework的 StopWatch 的源码解析。希望对大家有所帮助~~
参考文章：
https://coderdeepwater.cn/2021/01/05/java_source_code/nanoTime/
