效能指標| 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 飙高的情况,最终再次解决问题后系统性能有了显著提升。
因此,這個經驗再次驗證了“事出反常必有妖”,排查問題確實需要有耐心和系統性。