一文看懂：StopWatch 源码解读

Together for a Shared future

源码解读

最近项目有个耗时API，于是想办法定位分析慢的地方和原因，我第一时间想到了打log，但是胡乱打日志，不能有效帮我分析问题；此时，同事推荐了一个很有用的工具 -- StopWatch。

StopWatch介绍

常见的秒表工具类有几种：

1. 1. 1. 1. org.springframework.util.StopWatch

         2. org.apache.commons.lang.time.StopWatch

         3. 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个步骤：

1. new StopWatch();

2. clock.start(\"test1\");

3. clock.stop();

4. clock.prettyPrint();

1、新建StopWatch对象

源码：

/**
   * Construct a new {@code StopWatch}.
   * 
Does not start any task.
   */
  public StopWatch() {
    this(\"\");
  }


  /**
   * Construct a new {@code StopWatch} with the given ID.
   * 
The ID is handy when we have output from multiple stop watches and need
   * to distinguish between them.
   * 
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.
   * 
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();
  }

分析：

1. 1. 判断当前的计时任务是否停止：用的是一个乐观锁（currentTaskName 标志了 计时器 是否正在被某个任务占用）
      

      1.     currentTaskName 不为空：正在被某个任务占用，抛出异常

      2.     currentTaskName 为空：计时器重新计时
         

   2. 设置当前任务名称 currentTaskName

   3. 设置任务开始时间 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.
   * 
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);
    }


  }

分析：

1. 1. currentTaskName：乐观锁
      

      1.     currentTaskName 为空：没有进行中的测量Task，抛异常
         

      2.     currentTaskName 不为空：有进行中的Task
         

   2. 计算 lastTime ：System.nanoTime() - this.startTimeNanos;

   3. 计算 totalTimeNanos：this.totalTimeNanos += lastTime;

   4. 结束任务，构造测量结果，塞到任务列表里
      

      1.     构造 TaskInfo 对象
         

      2.     判断是否拓展 taskList 集合

         1. yes：放到 taskList 集合

         2. no：跳过，放弃该次任务收集
            

   5. 释放乐观锁：currentTaskName 置 null

4、计时器-结果输出

源码：

/**
   * Generate a string with a table describing all tasks performed.
   * 
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/