計時器工具 StopWatch

語言: CN / TW / HK

theme: geek-black

一起養成寫作習慣!這是我參與「掘金日新計劃 · 4 月更文挑戰」的第1天,點選檢視活動詳情

我是陳皮,一個在網際網路 Coding 的 ITer,個人微信公眾號「陳皮的JavaLib」關注第一時間閱讀最新文章。

前言

平常,我們想要統計某一段程式碼塊,或某一個方法的執行時間,最簡單的是採用如下的方式。

java  package com.chenpi;  ​  /**   * @author 陳皮   * @version 1.0   * @description   * @date 2022/4/2   */  public class ChenPi {  ​    public static void main(String[] args) throws InterruptedException {      long startTime = System.currentTimeMillis();      Thread.sleep(1000);      long endTime = System.currentTimeMillis();      System.out.println("執行耗時(ms):" + (endTime - startTime));   }  ​  }  ​  // 輸出結果如下  執行耗時(ms):1011

但如果我們想對多個程式碼段進行計時,以及每個階段計時的佔比等資訊,如果還是採用如上的方式就會充斥比較多的與業務無關的程式碼,不夠簡潔。

Spring StopWatch

Spring 框架有個工具類 StopWatch,它可以用來對程式中程式碼塊,或者方法進行計時,並且支援多階段計時,以及階段時間佔比等統計,使用起來程式碼比較簡潔,輕量。

java  package com.chenpi;  ​  import org.springframework.util.StopWatch;  ​  /**   * @author 陳皮   * @version 1.0   * @description   * @date 2022/4/2   */  public class ChenPi {  ​    public static void main(String[] args) throws InterruptedException {      // 宣告一個計時器      StopWatch stopWatch = new StopWatch("陳皮的計時器");      // 開始計時      stopWatch.start("傳送MQ計時");      Thread.sleep(1000);      // 結束計時      stopWatch.stop();      // 列印統計      System.out.println(stopWatch.prettyPrint());   }  ​  }  ​  ​  // 輸出結果如下  StopWatch '陳皮的計時器': running time = 1005775500 ns  ---------------------------------------------  ns         %     Task name  ---------------------------------------------  1005775500  100%  傳送MQ計時

Spring StopWatch 有以下幾個常用方法:

  • StopWatch():構造一個計時器
  • StopWatch(String id):構造一個指定 id 的計時器
  • start():建立一個名為空字串的計時任務,開始計時
  • start(String taskName):建立一個指定名稱計時任務,開始計時
  • stop():結束當前任務的計時
  • getTotalTimeNanos():獲取全部任務的執行時間,單位納秒
  • getTotalTimeMillis():獲取全部任務的執行時間,單位毫秒
  • shortSummary():獲取簡單的統計資訊
  • prettyPrint():以友好方式輸出總統計時間,以及各個階段任務的執行時間
  • setKeepTaskList(boolean keepTaskList):是否在內部的列表中儲存每一個任務

實踐例子

當程式中有多個計時器時,可通過構造不同 id 的計時器來區分。以下演示多個不同計時器,統計不同階段的執行時間。

java  package com.chenpi;  ​  import org.springframework.util.StopWatch;  ​  /**   * @author 陳皮   * @version 1.0   * @description   * @date 2022/4/2   */  public class ChenPi {  ​    public static void main(String[] args) throws InterruptedException {      m1();      m2();   }  ​    private static void m1() throws InterruptedException {  ​      // 宣告一個計時器      StopWatch stopWatch = new StopWatch("m1計時器");  ​      stopWatch.start("查詢資料庫");      Thread.sleep(1000);      stopWatch.stop();  ​      stopWatch.start("邏輯計算");      Thread.sleep(500);      stopWatch.stop();  ​      System.out.println(stopWatch.prettyPrint());   }  ​    private static void m2() throws InterruptedException {  ​      // 宣告一個計時器      StopWatch stopWatch = new StopWatch("m2計時器");  ​      stopWatch.start("遠端呼叫");      Thread.sleep(800);      stopWatch.stop();  ​      stopWatch.start("傳送MQ");      Thread.sleep(200);      stopWatch.stop();  ​      System.out.println(stopWatch.prettyPrint());   }  }  ​  // 輸出結果如下  StopWatch 'm1計時器': running time = 1516953200 ns  ---------------------------------------------  ns         %     Task name  ---------------------------------------------  1008091000  066%  查詢資料庫  508862200  034%  邏輯計算  ​  StopWatch 'm2計時器': running time = 1013080000 ns  ---------------------------------------------  ns         %     Task name  ---------------------------------------------  809345900  080%  遠端呼叫  203734100  020%  發生MQ

原始碼分析

其實 StopWatch 底層實現很簡單,對於每一個任務,在任務開始和結束時刻呼叫System.*nanoTime*()方法獲取伺服器當前的時間,然後計算每一個任務的執行時間,儲存在內部。內部使用一個列表儲存不同任務階段的執行時間,最後列印輸出。

```java package org.springframework.util;

import java.text.NumberFormat; import java.util.ArrayList; import java.util.List; import java.util.concurrent.TimeUnit;

import org.springframework.lang.Nullable;

public class StopWatch {

// 計時器id
private final String id;

// 是否將任務儲存到任務列表中
private boolean keepTaskList = true;

// 儲存全部任務的列表
private final List<TaskInfo> taskList = new ArrayList<>(1);

// 當前任務開始時間
private long startTimeNanos;

// 當前任務名稱
@Nullable
private String currentTaskName;

// 最後一個任務
@Nullable
private TaskInfo lastTaskInfo;

// 總任務數
private int taskCount;

// 總的執行時間
private long totalTimeNanos;

// 構造一個id為空字串的計時器
public StopWatch() {
    this("");
}

// 構造一個指定id的計時器
public StopWatch(String id) {
    this.id = id;
}

// 獲取計時器id
public String getId() {
    return this.id;
}

public void setKeepTaskList(boolean keepTaskList) {
    this.keepTaskList = keepTaskList;
}

// 開始計時
public void start() throws IllegalStateException {
    start("");
}

// 開始一個指定任務名稱的計時
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();
}

// 停止任務計時
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;
}

public boolean isRunning() {
    return (this.currentTaskName != null);
}

@Nullable
public String currentTaskName() {
    return this.currentTaskName;
}

public long getLastTaskTimeNanos() throws IllegalStateException {
    if (this.lastTaskInfo == null) {
        throw new IllegalStateException("No tasks run: can't get last task interval");
    }
    return this.lastTaskInfo.getTimeNanos();
}

public long getLastTaskTimeMillis() throws IllegalStateException {
    if (this.lastTaskInfo == null) {
        throw new IllegalStateException("No tasks run: can't get last task interval");
    }
    return this.lastTaskInfo.getTimeMillis();
}

public String getLastTaskName() throws IllegalStateException {
    if (this.lastTaskInfo == null) {
        throw new IllegalStateException("No tasks run: can't get last task name");
    }
    return this.lastTaskInfo.getTaskName();
}

public TaskInfo getLastTaskInfo() throws IllegalStateException {
    if (this.lastTaskInfo == null) {
        throw new IllegalStateException("No tasks run: can't get last task info");
    }
    return this.lastTaskInfo;
}

public long getTotalTimeNanos() {
    return this.totalTimeNanos;
}

public long getTotalTimeMillis() {
    return nanosToMillis(this.totalTimeNanos);
}

public double getTotalTimeSeconds() {
    return nanosToSeconds(this.totalTimeNanos);
}

public int getTaskCount() {
    return this.taskCount;
}

public TaskInfo[] getTaskInfo() {
    if (!this.keepTaskList) {
        throw new UnsupportedOperationException("Task info is not being kept!");
    }
    return this.taskList.toArray(new TaskInfo[0]);
}

public String shortSummary() {
    return "StopWatch '" + getId() + "': running time = " + getTotalTimeNanos() + " ns";
}

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();
}

@Override
public String toString() {
    StringBuilder sb = new StringBuilder(shortSummary());
    if (this.keepTaskList) {
        for (TaskInfo task : getTaskInfo()) {
            sb.append("; [").append(task.getTaskName()).append("] took ").append(task.getTimeNanos()).append(" ns");
            long percent = Math.round(100.0 * task.getTimeNanos() / getTotalTimeNanos());
            sb.append(" = ").append(percent).append('%');
        }
    }
    else {
        sb.append("; no task info kept");
    }
    return sb.toString();
}


private static long nanosToMillis(long duration) {
    return TimeUnit.NANOSECONDS.toMillis(duration);
}

private static double nanosToSeconds(long duration) {
    return duration / 1_000_000_000.0;
}

// 任務實體
public static final class TaskInfo {

    // 任務名稱
    private final String taskName;

    // 任務執行時間
    private final long timeNanos;

    TaskInfo(String taskName, long timeNanos) {
        this.taskName = taskName;
        this.timeNanos = timeNanos;
    }

    public String getTaskName() {
        return this.taskName;
    }

    public long getTimeNanos() {
        return this.timeNanos;
    }

    public long getTimeMillis() {
        return nanosToMillis(this.timeNanos);
    }

    public double getTimeSeconds() {
        return nanosToSeconds(this.timeNanos);
    }

}

} ```

StopWatch 使用起來簡潔,支援多工階段統計,統計多工時間佔比等,統計結果直觀。但是它也有不好的地方,就是一個 StopWatch 例項只能同時 start 一個 task,只能等這個 task 進行 stop 之後,才能繼續 start 另一個 task。注意,StopWatch 例項不是執行緒安全的,也沒必要進行同步處理。

lang3 StopWatch

Apache commons lang3 包下也有一個用於計時工具類 StopWatch。它還有暫停計時,恢復計時,設定分割點等功能。

groovy  org.apache.commons:commons-lang3:3.12.0

它主要有以下幾個常用方法:

  • create():例項化一個計時器
  • createStarted():例項化一個計時器,並開始計時
  • StopWatch(final String message):例項化一個帶有識別符號的計時器
  • start():開始計時
  • split():設定分割點
  • getSplitTime():統計從 start 開始最後一個分割點的用時
  • reset():重置計時
  • suspend():暫停計時
  • resume():恢復計時
  • stop():停止計時
  • getTime():統計從 start 到當前時刻的同時

java  package com.chenpi;  ​  import org.apache.commons.lang3.time.StopWatch;  ​  /**   * @author 陳皮   * @version 1.0   * @description   * @date 2022/4/2   */  public class ChenPi {  ​    public static void main(String[] args) throws InterruptedException {  ​      // 宣告一個計時器      StopWatch stopWatch = new StopWatch("m1計時器");  ​      stopWatch.start();      Thread.sleep(1000);      System.out.println("start開始到現在的時間:" + stopWatch.getTime());  ​      stopWatch.split();      Thread.sleep(500);      System.out.println("start開始到最後一個split的時間:" + stopWatch.getSplitTime());  ​      stopWatch.split();      Thread.sleep(500);      System.out.println("start開始到最後一個split的時間:" + stopWatch.getSplitTime());  ​      // 重置計時      stopWatch.reset();      Thread.sleep(2000);      stopWatch.start();      Thread.sleep(1000);      System.out.println("start開始到現在的時間:" + stopWatch.getTime());  ​      // 暫停計時      stopWatch.suspend();      Thread.sleep(3000);      // 恢復計時      stopWatch.resume();  ​      Thread.sleep(1000);  ​      // 結束計時      stopWatch.stop();  ​      Thread.sleep(1000);  ​      System.out.println("start開始到stop結束的時間:" + stopWatch.getTime());  ​      System.out.println(stopWatch);   }  }  ​  // 輸出結果如下  start開始到現在的時間:1000  start開始到最後一個split的時間:1001  start開始到最後一個split的時間:1510  start開始到現在的時間:1004  start開始到stop結束的時間:2015  m1計時器 00:00:02.015

總結

  • 如果是簡單的計算執行計時,可以使用 JDK 自帶的類獲取系統時間進行計時。
  • 如果需要多階段計時,並且需要統計每個階段的執行時間佔比等資訊,可以使用 StopWatch 工具類。
  • 推薦使用 Spring StopWatch,因為本身我們專案使用 Spring 框架比較多,這樣就自帶了 StopWatch。

本次分享到此結束啦~~

如果覺得文章對你有幫助,點贊、收藏、關注、評論,您的支援就是我創作最大的動力!