效能指標| CPU飆高排查實戰

問題發現

前段時間我們新上線了一個應用，由於流量一直不大，叢集的每秒查詢率（QPS）大約只有5。介面的響應時間大約在30 毫秒左右。

最近我們接入了新的業務，業務方提供的數據顯示，日常的QPS 預計可以達到2000，而在大促期間峰值QPS 可能會達到1 萬。

為了評估系統的性能水平，我們進行了壓力測試。測試在預發布環境進行。在壓力測試過程中，我們觀察到當單一伺服器的QPS 達到約200 時，介面的回應時間沒有明顯變化，但是CPU 使用率迅速上升，直到達到極限。

圖片圖片

壓力測試結束後，CPU 使用率立即下降。

隨後我們開始排查是什麼原因導致了CPU 的突然飆升。

排查與解決

在壓力測試期間，登入機器後，我們開始排查問題。

本案例的排查過程使用了阿里開源的Arthas 工具。如果沒有Arthas，也可以使用JDK 自帶的指令來排查。

在開始具體排查​​之前，可以先查看CPU 的使用情況。最簡單的方法是使用top指令直接查看：

top - 10:32:38 up 11 days, 17:56,  0 users,  load average: 0.84, 0.33, 0.18
Tasks:  23 total,   1 running,  21 sleeping,   0 stopped,   1 zombie
%Cpu(s): 95.5 us,  2.2 sy,  0.0 ni, 76.3 id,  0.0 wa,  0.0 hi,  0.0 si,  6.1 st
KiB Mem :  8388608 total,  4378768 free,  3605932 used,   403908 buff/cache
KiB Swap:        0 total,        0 free,        0 used.  4378768 avail Mem
   PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
   3480 admin     20   0 7565624   2.9g   8976 S  241.2 35.8 649:07.23 java
   1502 root      20   0  401768  40228   9084 S   1.0  0.5  39:21.65 ilogtail
   181964 root      20   0 3756408 104392   8464 S   0.7  1.2   0:39.38 java
   496 root      20   0 2344224  14108   4396 S   0.3  0.2  52:22.25 staragentd
   1400 admin     20   0 2176952 229156   5940 S   0.3  2.7  31:13.13 java
   235514 root      39  19 2204632  15704   6844 S   0.3  0.2  55:34.43 argusagent
   236226 root      20   0   55836   9304   6888 S   0.3  0.1  12:01.91 systemd-journ
  • 1.
  • 2.
  • 3.
  • 4.
  • 5.
  • 6.
  • 7.
  • 8.
  • 9.
  • 10.
  • 11.
  • 12.
  • 13.

可以清楚的看到，進程ID 為3480 的Java 進程佔用了較高的CPU，可以初步推斷是應用程式碼執行過程中消耗了大量的CPU 資源。接下來，我們需要進一步排查是哪個執行緒、哪段程式碼導致了這種情況。

首先，我們需要下載Arthas 工具：

curl -L https://arthas.aliyun.com/install.sh | sh
  • 1.

啟動：

./as.sh
  • 1.

使用Arthas 指令 "thread -n 3 -i 1000"查看目前"最忙"（耗CPU）的三個執行緒：

圖片圖片

透過上述堆疊資訊可以看出，佔用CPU 資源的執行緒主要是在JDBC 底層的TCP 套接字讀取上阻塞。經過連續執行多次分析，發現很多執行緒都在這個地方卡住。

進一步分析呼叫鏈後發現，這個問題源自於我程式碼中的資料庫insert 操作，其中使用了TDDL 來建立sequence。在sequence 的建立過程中，需要與資料庫互動。

根據對TDDL 的了解，它每次從資料庫查詢sequence 序列時，預設會取得1000 條，並在本地進行緩存，直到使用完這1000 條序列之後才會再次從資料庫取得下一個1000 條序列。

考慮到我們的壓測QPS 僅約為300 左右，不應該導致如此頻繁的資料庫互動。然而，透過多次使用Arthas 進行查看，發現大部分的CPU 資源都耗費在這裡。

因此，我們開始排查程式碼問題。最終，發現了一個非常簡單的問題，即我們的sequence 創建和使用存在著明顯的缺陷：

public Long insert(T dataObject) {

    if (dataObject.getId() == null) {
        Long id = next();
        dataObject.setId(id);
    }

    if (sqlSession.insert(getNamespace() + ".insert", dataObject) > 0) {
        return dataObject.getId();
    } else {
        return null;
    }
}

public Sequence sequence() {
    return SequenceBuilder.create()
        .name(getTableName())
        .sequenceDao(sequenceDao)
        .build();
}

/**
 * 获取下一个主键ID
 *
 * @return
 */
protected Long next() {
    try {
        return sequence().nextValue();
    } catch (SequenceException e) {
        throw new RuntimeException(e);
    }
}
  • 1.
  • 2.
  • 3.
  • 4.
  • 5.
  • 6.
  • 7.
  • 8.
  • 9.
  • 10.
  • 11.
  • 12.
  • 13.
  • 14.
  • 15.
  • 16.
  • 17.
  • 18.
  • 19.
  • 20.
  • 21.
  • 22.
  • 23.
  • 24.
  • 25.
  • 26.
  • 27.
  • 28.
  • 29.
  • 30.
  • 31.
  • 32.
  • 33.

因此，我們每次執行insert 語句時都重新建構了一個新的sequence 對象，這導致本地快取被清空。因此，每次都需要從資料庫重新取得1000 條sequence，但實際上只使用了一條，下次又會重複這個過程。

為了解決這個問題，我們調整了程式碼，在應用程式啟動時初始化了一個Sequence 實例。這樣，在後續取得sequence 時，就不會每次都與資料庫互動。而是先檢查本地緩存，只有在本地緩存用盡時才會再次與資料庫交互，獲取新的sequence。

public abstract class BaseMybatisDAO implements InitializingBean {
        @Override
        public void afterPropertiesSet() throws Exception {
            sequence = SequenceBuilder.create().name(getTableName()).sequenceDao(sequenceDao).build();
        }
    }
  • 1.
  • 2.
  • 3.
  • 4.
  • 5.
  • 6.

透過實作InitializingBean 接口，並重寫其中的afterPropertiesSet()方法，在該方法中進行Sequence 的初始化。

完成以上程式碼修改後，提交並進行驗證。根據監控數據顯示，優化後資料庫的讀取回應時間（RT）明顯下降。

圖片圖片

sequence 的寫入操作QPS 也有明顯下降：

圖片圖片

於是我們開始了新的一輪壓測，但發現CPU 的使用率仍然很高，壓測的QPS 還是無法達到預期。因此，我們決定重新使用Arthas 工具查看線程的情況。

圖片圖片

發現了一個CPU 消耗較高的線程堆疊，主要是因為我們在使用一個聯調工具時，該工具預發布狀態下默認開啟了TDDL 的日誌採集（儘管官方文檔中描述預發布狀態下默認不會開啟TDDL 採集，但實際上確實會進行採集）。

在該工具列印日誌時，會進行資料脫敏操作，而脫敏框架使用了Google 的re2j 進行正規表示式匹配。

由於我的操作涉及大量的TDDL 操作，而預設會擷取大量TDDL 日誌並進行脫敏處理，這導致了較高的CPU 消耗。

因此，透過在預發布環境中關閉對TDDL 的日誌擷取，可以有效解決這個問題。

總結

這篇總結回顧了一次線上CPU 飆高問題的排查過程，雖然問題最終解決起來並不複雜，但排查過程中卻有其獨特的教育意義。

之前經驗豐富的我按照慣例進行了排查，初始階段並未發現明顯問題，錯誤地將資料庫操作增加歸因於流量上升所致的正常情況。

透過多方查證（例如使用arthas 查看序列獲取情況，以及透過資料庫查詢最新插入資料的主鍵ID 等方法），最終確認問題出在TDDL 的序列初始化機制上。

解决了这个问题后，本以为问题彻底解决，却又遭遇到 DP 采集 TDDL 日志导致 CPU 飙高的情况，最终再次解决问题后系统性能有了显著提升。

因此，這個經驗再次驗證了“事出反常必有妖”，排查問題確實需要有耐心和系統性。