一次排查線上接口偶發異常耗時引發的思考！

時間 2020-07-11

標籤一次排查線上接口偶發異常耗時引發思考欄目興趣愛好简体版

原文原文鏈接

1、引子

這要從線上的一個接口偶發異常耗時提及，事情每每不是你想象的樣子，尤爲是在排查問題的時候，切忌有先入爲主的的某些判斷。spring

2、問題：

接口監控圖：顯示天天總會有那麼幾回耗時特別長的請求。apache

3、排查：spa

一、直觀的認識是「偶發」，天天零星的幾個，不規律。

對於這種狀況，第一感受是由於服務的波動影響，由於沒有服務可以達到100%的低延遲可用響應。pwa

首先檢查了相應時段的其它接口的響應狀況，發現並無類似的情景。由此能夠基本上排除了服務波動的影響，可是也不是十分肯定。code

二、接口邏輯

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

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

三、不得已而爲之

通過以上幾步的排查，現有的信息已經不足以定位問題了。只能把接口裏的每一步邏輯耗時所有統計記錄來進一步排查（其實，心裏是很是拒絕的）。接口

4、StopWatch

StopWatch不少地方都提供了，Spring、Apache、Guava。get

一、Spring示例：it

♣ 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

二、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

三、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));
    }

輸出：