一文看懂:StopWatch 源码解读

发布时间:2024-02-19 16:30

\"9281641331fce8f1b91c21c1e8792473.png\"

Together for a Shared future

源码解读

\"fd7b12c5e447d9582132088f5241ee9f.png\"

\"3ebee2a0a8560a381d1861fffdbc1c50.png\"

\"e55a8b4e61d3e2c4c25d4655a18f625f.png\"

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

\"e1b15ba0387dfb84b328b4ea595b0789.png\"

StopWatch介绍

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

        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毫秒左右)。

\"c9acc1fba8ddf6cfdb63339e946b1f68.png\"

应用案例

@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

\"13e48861e1c992cfc69b301ebd7090ff.png\"

源码分析

以上面的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. 判断当前的计时任务是否停止:用的是一个乐观锁(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. 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的源码解析,确实是挺简单的一个工具类。

\"06c9c4b92f4212c8f7f220550e9042c5.png\"

StopWatch的其他能力

下面是StopWatch的方法列表:

\"一文看懂:StopWatch

\"100c2ba6fa3aa22698b691f89abb2cc0.png\"

不足

StopWatch对象不是设计为线程安全的,并且不使用同步。一般是在开发过程中验证性能,而不是作为生产应用程序的一部分。

\"2fa7c5559536c8a61ee119dd887cf933.png\"

总结

上面是spring-framework的 StopWatch 的源码解析。希望对大家有所帮助~~

参考文章:

https://coderdeepwater.cn/2021/01/05/java_source_code/nanoTime/

\0\0\0\0

ItVuer - 免责声明 - 关于我们 - 联系我们

本网站信息来源于互联网,如有侵权请联系:561261067@qq.com

桂ICP备16001015号