還在用new Date計算任務執(zhí)行時間?強烈建議使用這個API!
在實踐過程中,我們經(jīng)常需要記錄一個任務執(zhí)行的耗時,這是評價代碼好壞,評測代碼性能,排查業(yè)務執(zhí)行問題的重要操作。那么,你是如何來獲取并計算任務執(zhí)行耗時的呢?通過new Date獲得時間進行換算?還是有更好的方案?本文給你答案。
獲取任務耗時通常做法
獲取任務耗時,最簡單的方式就是打印當前時間與任務開始執(zhí)行時間的差值,實例代碼如下:
- @Test
- public void testElapsedTimes() throws InterruptedException {
- long startTime = new Date().getTime();
- // do something
- Thread.sleep(1000);
- System.out.println("執(zhí)行耗時:" + (new Date().getTime() - startTime) + "ms");
- }
上述方式實現(xiàn)簡單,邏輯也比較直觀。但如果執(zhí)行大量測試,測試中還有不同的代碼邏輯塊,那么需要改動的地方就比較多。
改進做法
在上述代碼中,如果IDE安裝有代碼檢查工具,則會提示采用System.currentTimeMillis()來獲取時間,而不是new Date().getTime()的方式。
改造之后,實現(xiàn)代碼如下:
- @Test
- public void testElapsedTimes1() throws InterruptedException {
- long startTime = System.currentTimeMillis();
- // do something
- Thread.sleep(1000);
- System.out.println("執(zhí)行耗時:" + (System.currentTimeMillis() - startTime) + "ms");
- }
在這樣的場景下(無需獲取更多Date相關信息)也推薦使用System.currentTimeMillis()來獲取時間戳。至于為什么,看一下Date的源碼實現(xiàn)就知道了。
Date的構造方法:
- public Date() {
- this(System.currentTimeMillis());
- }
Date在構造時,本質上也是先獲得了System.currentTimeMillis(),然后再初始化其他信息。既然我們只需要時間戳,那就沒必要再構建Date對象了。從性能層面來說,能優(yōu)化則優(yōu)化。
Spring的StopWatch
上述兩種方式雖然性能和寫法有所區(qū)別,但本質是一樣的。下面我們來講講Spring提供的StopWatch類,它不僅可實現(xiàn)上述功能,而且還可以做類似任務執(zhí)行時間控制,也就是封裝了一個對開始時間、結束時間記錄操作的Java類。
先通過StopWatch類來實現(xiàn)一下上述功能:
- @Test
- public void testStopWatch() throws InterruptedException {
- StopWatch sw = new StopWatch();
- sw.start("開始執(zhí)行業(yè)務");
- // do something
- Thread.sleep(1000);
- sw.stop();
- System.out.println(sw.getTotalTimeMillis());
- }
通過創(chuàng)建StopWatch對象,然后調(diào)用它的start、stop方法來區(qū)分執(zhí)行任務區(qū)間,通過getTotalTimeMillis()方法獲得總耗時。
乍一看,代碼好像還比之前的方式多了,體現(xiàn)不出來什么優(yōu)勢啊!下面我們再來看一個復雜點的示例:
- @Test
- ublic void testStopWatch1() throws InterruptedException {
- StopWatch sw = new StopWatch();
- sw.start("起床");
- Thread.sleep(1000);
- sw.stop();
- sw.start("洗漱");
- Thread.sleep(2000);
- sw.stop();
- sw.start("鎖門");
- Thread.sleep(500);
- sw.stop();
- System.out.println(sw.prettyPrint());
- System.out.println(sw.getTotalTimeMillis());
- System.out.println(sw.getLastTaskName());
- System.out.println(sw.getLastTaskInfo());
- System.out.println(sw.getTaskCount());
執(zhí)行上述測試示例,打印結果如下:
- StopWatch '': running time = 3509166972 ns
- ---------------------------------------------
- ns % Task name
- ---------------------------------------------
- 1003330360 029% 起床
- 2001421734 057% 洗漱
- 504414878 014% 鎖門
- 3509
- 鎖門
- org.springframework.util.StopWatch$TaskInfo@12f40c25
- 3
此時,看到StopWatch的魅力所在了嗎?
- 通過多組start、stop方法,將業(yè)務代碼塊進行區(qū)分,可獲得不同代碼塊的執(zhí)行耗時;
- 可以通過start方法傳入taskName,對每個代碼塊進行命名;
- 可以對總任務耗時、每個任務耗時進行統(tǒng)計分析;
- prettyPrint()方法,可以優(yōu)雅的打印出統(tǒng)計分析信息;
- getTotalTimeMillis()方法,打印出總耗時;
- getLastTaskName()方法,打印最后一個任務名稱;
- getLastTaskInfo()方法,獲得最后一個任務的TaskInfo,進而獲得更多相關信息;
- getTaskCount()方法,獲得任務數(shù);
現(xiàn)在再看,使用StopWatch是不是可以獲得更多有用的信息?
StopWatch的實現(xiàn)原理
最后呢,我們再來看一眼源碼,了解一下StopWatch的實現(xiàn)機制。
先看StopWatch的start方法實現(xiàn):
- 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();
- }
start方法中記錄了任務名稱和任務執(zhí)行的時間,基于System.nanoTime()獲得。
stop方法實現(xiàn)如下:
- 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;
- }
在stop方法中,通過兩個時間戳相減獲得lastTime,也就是一個任務的執(zhí)行時間;lastTime累計相加獲得總的執(zhí)行時間;同時,記錄任務列表、任務數(shù)統(tǒng)計。
而其他get方法,則是對start、stop中獲取的數(shù)據(jù)的進一步統(tǒng)計、分析、格式化輸出而已。
小結
有些功能當我們使用習慣了,可能就固守于一個實現(xiàn)方式,但如果去參考學習其他框架中類似功能的實現(xiàn),往往會有些新的突破。如果你在使用Spring的框架,建議你嘗試一下StopWatch這個API,可以讓你的時間統(tǒng)計日志更加高端大氣。