效能指標| 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 飙高的情况,最终再次解决问题后系统性能有了显著提升。

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