统计代码块耗时的小工具stopwatch

迷南。 2022-10-09 04:49 229阅读 0赞

相信很多人都遇到这样一个问题？

加班加点，上线了一个功能，但接口的响应时间有点长？

如何定位排查？

普通研发人员一般会采用下面方式，在很多位置点埋入开始时间戳、结束时间戳，相减便得到耗时。代码如下：

long start1 = System.currentTimeMillis();
    // 模拟业务逻辑处理
    Thread.sleep(300);
    long end1 = System.currentTimeMillis();
    
    long start2 = System.currentTimeMillis();
    // 模拟业务逻辑处理
    Thread.sleep(730);
    long end2 = System.currentTimeMillis();
    
    System.out.println("执行操作1，耗时:" + (end1 - start1));
    System.out.println("执行操作2，耗时:" + (end2 - start2));

虽然书写简单，但导致系统中充斥着大量低级代码，比较烦人，很容易让人怀疑你的技术实力。

我们的直接想法是能不能写个工具类，即统计`代码块`耗时，还能将分析结果直观展示出来

恰好 Spring框架提供了一个工具类，`org.springframework.util.StopWatch`，提供了轻量级统计功能，对应的pom文件依赖

<dependency>
        <groupId>org.springframework</groupId>
        <artifactId>spring-core</artifactId>
        <version>5.2.9.RELEASE</version>
    </dependency>

StopWatch 源码

省略。。。
    public void start(String taskName) throws IllegalStateException {
        if (this.currentTaskName != null) {
            throw new IllegalStateException("Can't start StopWatch: it's already running");
        } else {
            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");
        } else {
            long lastTime = System.nanoTime() - this.startTimeNanos;
            this.totalTimeNanos += lastTime;
            this.lastTaskInfo = new StopWatch.TaskInfo(this.currentTaskName, lastTime);
            if (this.keepTaskList) {
                this.taskList.add(this.lastTaskInfo);
            }
    
            ++this.taskCount;
            this.currentTaskName = null;
        }
    }
    
    省略。。。

start与stop方法分别记录开始时间与结束时间。

其中在记录结束时间时，会维护一个链表类型的`tasklist`属性，从而使该类可记录多个任务，最后的输出也仅仅是对之前记录的信息做了一个统一的归纳输出，从而使结果更加直观的展示出来。

prettyPrint方法，可直观的输出代码执行耗时，以及执行时间百分比。

**StopWatch 优点**：

*  Spring框架自带，操作简单，开箱即用
 *  任务start时可以指定name，显示更加友好
 *  数据归纳，展示每项任务耗时与占用总时间的百分比，展示结果直观

**缺点：**

*  一个`StopWatch`不能同时启动多个任务，必须在当前任务`stop`之后才能开启新的task。若要一次开启多个，需要new一个新的`StopWatch`实例
 *  代码有侵入性

代码示例：

StopWatch sw = new StopWatch();
    sw.start("任务1");
    // 模拟业务逻辑处理
    Thread.sleep(300);
    sw.stop();
    
    sw.start("任务2");
    // 模拟业务逻辑处理
    Thread.sleep(730);
    sw.stop();
    
    System.out.println(sw.prettyPrint());

运行结果：

StopWatch '': running time (millis) = 1033
    -----------------------------------------
    ms     %     Task name
    -----------------------------------------
    00303  029%  任务1
    00730  071%  任务2

## 类似工具 ##

除了上面 `Spring` 提供了工具外，apache下的`org.apache.commons.lang.time.StopWatch` 和 Guava 下的`com.google.common.base.Stopwatch` 都提供了类似的工具

大家根据自己的喜好，选择使用。原理大同小异，只是编码风格略有不同。

## 项目源码地址 ##

https://github.com/aalansehaiyang/spring-boot-bulking  
    
    模块：spring-boot-bulking-tool

> 最后，阿里巴巴还开源一种系统诊断工具（Arthas），支持在线分析系统瓶颈，并提供了丰富的命令行操作，感兴趣的同学可以体验。