1、前言
最近项目有个耗时 API，于是想办法定位分析慢的地方和原因，我第一时间想到了打 log，但是胡乱打日志，不能有效帮我分析问题；此时，同事推荐了一个很有用的工具 -- StopWatch。
2、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 毫秒左右）。
3、应用案例
@Controller@RequestMapping("/app")@Slf4jpublic 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% test1000101042 001% test2000045750 000% test3
复制代码
4、源码分析
以上面的 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 为空：没有进行中的测量 Task，抛异常
currentTaskName 不为空：有进行中的 Task
构造 TaskInfo 对象
判断是否拓展 taskList 集合
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 的源码解析，确实是挺简单的一个工具类。
5、StopWatch 的其他能力
下面是 StopWatch 的方法列表：
5.1 不足
StopWatch 对象不是设计为线程安全的，并且不使用同步。一般是在开发过程中验证性能，而不是作为生产应用程序的一部分。
5.2 总结
上面是 spring-framework 的 StopWatch 的源码解析。希望对大家有所帮助~~
参考文章：
https://coderdeepwater.cn/2021/01/05/java_source_code/nanoTime/
评论