Apache和Spring提供的StopWatch執行時間監視器

_YourBatman發表於2019-07-28

相關閱讀

【小家java】java5新特性(簡述十大新特性) 重要一躍
【小家java】java6新特性(簡述十大新特性) 雞肋升級
【小家java】java7新特性(簡述八大新特性) 不溫不火
【小家java】java8新特性(簡述十大新特性) 飽受讚譽
【小家java】java9新特性(簡述十大新特性) 褒貶不一
【小家java】java10新特性(簡述十大新特性) 小步迭代
【小家java】java11新特性(簡述八大新特性) 首個重磅LTS版本


前言

編碼過程中我們經常會希望得到一段程式碼(一個方法)的執行時間,本文將介紹兩種時間監視器(秒錶)來讓你優雅的、靈活的處理這個問題。

Java源生方式

這種方式最最簡單,最好理解,當然也是最為常用:我們自己書寫。
例如:我們如果要統計一段程式碼的執行時間,經常會這麼來寫:

    public static void main(String[] args) {
        long startTime = System.currentTimeMillis();   //獲取開始時間

        //函式主體程式碼
        //...

        long endTime = System.currentTimeMillis(); //獲取結束時間
        System.out.println("程式執行時間: " + (endTime - startTime) + "ms");
    }

大多數時候我們使用ms來表示即可,但是這麼寫缺乏靈活性。倘若我們要展示成納秒、秒、甚至分鐘,還得我們自己處理(把毫秒值拿來進行轉換~ )

當然可能到了JDK8以後,我們這麼做能變得稍微靈活一些:可以這麼處理:

    public static void main(String[] args) {
        Instant start = Instant.now();
        //doSomething();
        Instant end = Instant.now();

        Duration duration = Duration.between(start, end);
        System.out.println("millis = " + duration.toMillis());
    }

這個比上面靈活度強一些。但也還是有一定的缺點:步驟稍顯複雜,總體上還是不夠優雅,也不是那麼的靈活。
那麼本文針對此問題介紹一個工具:StopWatch執行時間監視器。藉助它來統計我們程式的執行時間,帶給非常多的方便和優雅。

StopWatch需要依賴額外的Jar:commons-lang3或者spring-core,但因這兩個Jar是Java開發中都必導的,因此依賴相容性方面可以忽略

StopWatch有很多開源的框架都有提供類似的功能:比如Apache的commons-lang3,當然還有Spring framwork自己提供的,本文將針對此倆分別做介紹~

Commons-lang3的StopWatch

Apache提供的這個任務執行監視器功能豐富強大(比Spring的強大),靈活性強,如下經典實用案例:

    public static void main(String[] args) throws Exception {
        StopWatch watch = StopWatch.createStarted(); //建立後立即start,常用
        //StopWatch watch = new StopWatch();
        //watch.start();

        Thread.sleep(1000);
        System.out.println("統計從開始到現在執行時間:" + watch.getTime() + "ms"); //1000ms

        Thread.sleep(1000);
        watch.split();
        System.out.println("從start到此刻為止的時間:" + watch.getTime());
        System.out.println("從開始到第一個切入點執行時間:" + watch.getSplitTime()); //2245

        Thread.sleep(1000);
        watch.split();
        System.out.println("從開始到第二個切入點執行時間:" + watch.getSplitTime());

        watch.reset(); //重置後必須使用start方法
        watch.start();
        Thread.sleep(1000);
        System.out.println("重新開始後到當前執行時間是:" + watch.getTime()); //1000

        watch.suspend(); //暫停
        Thread.sleep(6000); //模擬暫停6秒鐘

        watch.resume(); //上面suspend,這裡要想重新統計,需要恢復一下
        System.out.println("恢復後執行的時間是:" + watch.getTime()); //1000  注意此時這個值還是1000

        watch.stop();
        System.out.println("花費的時間》》" + watch.getTime() + "ms"); //1002ms
        System.out.println("花費的時間》》" + watch.getTime(TimeUnit.SECONDS) + "s"); //1s 可以直接轉成s

    }

列印結果:

統計從開始到現在執行時間:1007ms
從start到此刻為止的時間:2008
從開始到第一個切入點執行時間:2008
從開始到第二個切入點執行時間:3009
重新開始後到當前執行時間是:1000
恢復後執行的時間是:1000
花費的時間》》1001ms
花費的時間》》1s

如上就是StopWatch的基本使用方法,足以見到了它的強大吧,當然使用起來複雜度也是提升了些的。

核心原理解釋

原理相對簡單,簡單看看原始碼便知:

// @since 2.0
public class StopWatch {
    // @since 3.5  這個靜態方法出現得稍微晚點哦~
    public static StopWatch createStarted() {
        final StopWatch sw = new StopWatch();
        sw.start();
        return sw;
    }

    // 這些成員變數是實現的核心~~~~~~~~~~~~~~
    private State runningState = State.UNSTARTED;
    private SplitState splitState = SplitState.UNSPLIT;
    private long startTime;
    // 思考:為何有了nonaTime這裡還得記錄一個Millis Time呢???
    // 因為nanoTime只能拿來計算差值(耗時) 但是getStartTime()這個老API還得靠MillsTime~~~
    private long startTimeMillis;
    private long stopTime;
    
    // 可見:start方法可不是能夠多次呼叫的哦~~和狀態是有關的
    public void start() {
        if (this.runningState == State.STOPPED) {
            throw new IllegalStateException("Stopwatch must be reset before being restarted. ");
        }
        if (this.runningState != State.UNSTARTED) {
            throw new IllegalStateException("Stopwatch already started. ");
        }
        this.startTime = System.nanoTime();
        this.startTimeMillis = System.currentTimeMillis();
        this.runningState = State.RUNNING;
    }

    // 停表時,最重要的是記錄下了stopTime 的值~~~然後標記狀態
    public void stop() {
        if (this.runningState != State.RUNNING && this.runningState != State.SUSPENDED) {
            throw new IllegalStateException("Stopwatch is not running. ");
        }
        if (this.runningState == State.RUNNING) {
            this.stopTime = System.nanoTime();
        }
        this.runningState = State.STOPPED;
    }

    // 狀態變為非開始狀態...
    public void reset() {
        this.runningState = State.UNSTARTED;
        this.splitState = SplitState.UNSPLIT;
    }

    // 暫停:stopTime 也給了一個值
    public void suspend() {
        if (this.runningState != State.RUNNING) {
            throw new IllegalStateException("Stopwatch must be running to suspend. ");
        }
        this.stopTime = System.nanoTime();
        this.runningState = State.SUSPENDED;
    }

    // 這兩個方法是獲取差值的
    public long getTime() {
        return getNanoTime() / NANO_2_MILLIS;
    }
    // @since 3.5
    public long getTime(final TimeUnit timeUnit) {
        return timeUnit.convert(getNanoTime(), TimeUnit.NANOSECONDS);
    }

    // @since 2.4 老API  這叫獲取啟動的時間(啥時候啟動的)
    public long getStartTime() {
        if (this.runningState == State.UNSTARTED) {
            throw new IllegalStateException("Stopwatch has not been started");
        }
        // System.nanoTime is for elapsed time
        return this.startTimeMillis;
    }
}

可以看到原理是很簡單的,無非就是包裝了暫停、回覆、split等功能嘛

使用細節

==getTimegetSplitTime有啥區別呢?==
為了說明問題,此處我們看看getNanoTime()getSplitNanoTime()亦可:

    public long getNanoTime() {
        if (this.runningState == State.STOPPED || this.runningState == State.SUSPENDED) {
            return this.stopTime - this.startTime;
        } else if (this.runningState == State.UNSTARTED) {
            return 0;
        } else if (this.runningState == State.RUNNING) {
            return System.nanoTime() - this.startTime;
        }
        throw new RuntimeException("Illegal running state has occurred.");
    }

    public long getSplitNanoTime() {
        if (this.splitState != SplitState.SPLIT) {
            throw new IllegalStateException("Stopwatch must be split to get the split time. ");
        }
        return this.stopTime - this.startTime;
    }

我們發現:

  • 呼叫getSplit...相關方法前,必須先呼叫Split方法

spilit()方法原始碼如下:

    public void split() {
        if (this.runningState != State.RUNNING) {
            throw new IllegalStateException("Stopwatch is not running. ");
        }
        this.stopTime = System.nanoTime();
        this.splitState = SplitState.SPLIT;
    }

在呼叫split方法後,watch的狀態改為了SPLIT且,且,且stopTime 設定為了當前時間。因此此處我們的stopTime停止了,這個時候呼叫getSplitNanoTime(),返回的是start到split那時的時間差值。因此用此方法可以插入先停止stopTime()(有點插隊的趕腳),最後再輸出(先插好隊,最後在輸出)~

getTime()就是拿當前的時間戳,減去startTime,一般不涉及到stopTime的值,因此splitTime處理計算時間顯然更加的靈活,但是,一般我們使用getTime()就足夠了

Spring的StopWatch

Spring提供的這個任務監視器,我還是蠻喜歡使用的,因為一個它能夠幫我同事監控多個任務,使用起來也很方便。先看一個簡單的使用案例:

注意:一個監視器能夠記錄多個任務的執行時間這個特點非常重要哦~
比如:我們可以記錄多段程式碼耗時時間,然後一次性列印~

    public static void main(String[] args) throws Exception {
        // 強烈每一個秒錶都給一個id,這樣檢視日誌起來能夠更加的精確
        // 至於Id 我覺得給UUID是可行的~
        StopWatch sw = new StopWatch(UUID.randomUUID().toString());

        sw.start("起床");
        Thread.sleep(1000);
        System.out.println("當前任務名稱:" + sw.currentTaskName());
        sw.stop();

        sw.start("洗漱");
        Thread.sleep(2000);
        System.out.println("當前任務名稱:" + sw.currentTaskName());
        sw.stop();

        sw.start("鎖門");
        Thread.sleep(500);
        System.out.println("當前任務名稱:" + sw.currentTaskName());
        sw.stop();

        System.out.println(sw.prettyPrint()); // 這個方法列印在我們記錄日誌時是非常友好的  還有百分比的分析哦
        System.out.println(sw.shortSummary());
        System.out.println(sw.currentTaskName()); // stop後它的值為null


        // 最後一個任務的相關資訊
        System.out.println(sw.getLastTaskName());
        System.out.println(sw.getLastTaskInfo());

        // 任務總的耗時  如果你想獲取到每個任務詳情(包括它的任務名、耗時等等)可使用
        System.out.println("所有任務總耗時:" + sw.getTotalTimeMillis());
        System.out.println("任務總數:" + sw.getTaskCount());
        System.out.println("所有任務詳情:" + sw.getTaskInfo()); // 拿到所有的任務
    }

列印:

當前任務名稱:起床
當前任務名稱:洗漱
當前任務名稱:鎖門
StopWatch 'd6ba9412-d551-4ba7-8b0e-1b7ccb42855d': running time (millis) = 3504
-----------------------------------------
ms     %     Task name
-----------------------------------------
01001  029%  起床
02000  057%  洗漱
00503  014%  鎖門

StopWatch 'd6ba9412-d551-4ba7-8b0e-1b7ccb42855d': running time (millis) = 3504
null
鎖門
org.springframework.util.StopWatch$TaskInfo@2d554825
所有任務總耗時:3504
任務總數:3
所有任務詳情:[Lorg.springframework.util.StopWatch$TaskInfo;@68837a77

我個人偏愛使用Spring提供的這個監視器,是因為它提供的prettyPrint()列印在日誌裡進行分析可以非常的直觀,並且我覺得提供的多工支援也更加實用一點,當然僅僅個人偏好而已~

最後

很多時候,寫程式碼也是一種藝術,而藉助這種實用工具我就覺得藝術感更強些。希望我們能有追求更加美好事物的心,這點對於接納新知識特別重要。此處推薦這個監視器來代替之前的的使用,能讓小夥伴們更加靈活的分析你的程式碼~

知識交流

若文章格式混亂,可點選原文連結-原文連結-原文連結-原文連結-原文連結

==The last:如果覺得本文對你有幫助,不妨點個讚唄。當然分享到你的朋友圈讓更多小夥伴看到也是被作者本人許可的~==

若對技術內容感興趣可以加入wx群交流:Java高工、架構師3群
若群二維碼失效,請加wx號:fsx641385712(或者掃描下方wx二維碼)。並且備註:"java入群" 字樣,會手動邀請入群

相關文章