一次排查線上介面偶發異常耗時引起的思考！

WindWant發表於2020-07-11

一、引子

這要從線上的一個介面偶發異常耗時說起，事情往往不是你想象的樣子，尤其是在排查問題的時候，切忌有先入為主的的某些判斷。

二、問題：

介面監控圖：顯示每天總會有那麼幾次耗時特別長的請求。

三、排查：

1、直觀的認識是“偶發”，每天零星的幾個，不規律。

對於這種情況，第一感覺是因為服務的波動影響，因為沒有服務能夠達到100%的低延遲可用響應。

首先檢查了相應時段的其它介面的響應情況，發現並沒有相似的情景。由此可以基本上排除了服務波動的影響，但是也不是十分確定。

2、介面邏輯

 

邏輯l3是一個存在很久的歷史業務邏輯，首先假定認為了它沒有問題排除掉了（呵呵）。

l2是一個比較耗時的處理，首先的關注點放在了這裡。l2是有超時設定的，最大超時為2s，但是我們的監控庫裡看到的最大的耗時是超過兩秒的，或者考慮到其它處理邏輯的耗時，最壞的情況下，總的耗時是不應該超過3s的。為了確認l2服務的穩定性，線上新增了相應的監控，觀察到最大耗時是在超時限定範圍內的。因此排除掉此處的問題，

3、不得已而為之

經過以上幾步的排查，現有的資訊已經不足以定位問題了。只能把介面裡的每一步邏輯耗時全部統計記錄來進一步排查（其實，內心是非常拒絕的）。

四、StopWatch

StopWatch很多地方都提供了，Spring、Apache、Guava。

1、Spring示例：

♣ id標識當前的StopWatch，比如統計一個介面的耗時，可以使用介面名稱作為標識，從而在輸出端進行識別。

♣ 內部有task概念，用以表示內部每一階段的執行邏輯，比如獲取使用者資訊->獲取資金資訊->交易邏輯流轉過程。

♣ 的格式化輸出比較明晰，包括StopWatch標識，任務標識，每個任務的耗時及總佔比。

public static void springStopWatch() throws InterruptedException {
        StopWatch stopWatch = new StopWatch("spring_stopwatch");
        stopWatch.start("a"); //開始任務a
        Thread.sleep(1000);
        stopWatch.stop(); //任務a執行完畢
        stopWatch.start("b"); //開始任務b
        Thread.sleep(2000);
        stopWatch.stop(); //任務b執行完畢
        stopWatch.start("c"); //開始任務c
        Thread.sleep(100);
        stopWatch.stop(); //任務c執行完畢
        System.out.println(stopWatch.prettyPrint());
    } 

輸出：

StopWatch 'spring_stopwatch': running time (millis) = 3111
-----------------------------------------
ms     %     Task name
-----------------------------------------
01002  032%  a
02006  064%  b
00103  003%  c

2、Apache StopWatch：

這裡有個split概念，我願意稱之為時間“錨點”，當你執行完split操作後，在下一次執行split之前，你可以在任何時候獲取開始時間到執行split的時間點之間的時間間隔：

supend-resume：掛起、恢復，很容易理解，暫停計時、恢復繼續計時：

public static void apacheStopWatch() throws InterruptedException {
        org.apache.commons.lang3.time.StopWatch stopWatch = org.apache.commons.lang3.time.StopWatch.createStarted();
        Thread.sleep(1000);
        stopWatch.stop(); //結束計時
        System.out.println("normal: " + stopWatch.getTime());

        //split test
        stopWatch.reset();
        stopWatch.start();
        Thread.sleep(1000);
        stopWatch.split(); //時間錨點
        Thread.sleep(1000);
        System.out.println("split: " + stopWatch.getSplitTime()); //開始到時間錨點的間隔

        //suspend
        stopWatch.reset();
        stopWatch.start();
        Thread.sleep(1000);
        stopWatch.suspend(); //掛起watch
        Thread.sleep(1000); //期間的時間是不計入總時間的
        stopWatch.resume(); //恢復watch
        Thread.sleep(1000);
        stopWatch.stop();
        System.out.println("suspend_resume: " + stopWatch.getTime());
    }

輸出：

normal: 1002
split: 1004
suspend_resume: 2009

3、Guava：

just StopWatch

public static void guavaStopWatch() throws InterruptedException {
        Stopwatch stopwatch = Stopwatch.createStarted();
        Thread.sleep(1000);
        stopwatch.stop();
        System.out.println(stopwatch.elapsed(TimeUnit.MILLISECONDS));
        stopwatch.reset();
        stopwatch.start();
        Thread.sleep(2000);
        stopwatch.stop();
        System.out.println(stopwatch.elapsed(TimeUnit.MILLISECONDS));
    }

輸出：

1001
2004

五、結論

這裡採用的是Spring的StopWatch，四個Task，總耗時及分耗時不用額外的記錄處理，對於總耗時超過一定值的請求，列印StopWatch明細：

 

問題就在那個一開始就認定不會有問題的邏輯裡。

其實本篇的出發點並不是要描述什麼疑難線上問題的排查過程、方法、技巧。

當我們面對問題時，真正阻我們，或者說會把我們引向錯誤方向的正式我們所固有的一種慣性認知，思維模式。

任何時候對於未知，不要輕易去假定任何不確定的東西，經驗可以是助益，同時也可能成為阻礙。

問題面前，一切都值得懷疑，平等的懷疑。

 

相關文章