前段時間我們新上線了一個應用,由于流量一直不大,集群的每秒查詢率(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.18Tasks: 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 stKiB Mem : 8388608 total, 4378768 free, 3605932 used, 403908 buff/cacheKiB 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
可以清楚的看到,進程 ID 為 3480 的 Java 進程占用了較高的 CPU,可以初步推斷是應用代碼執行過程中消耗了大量的 CPU 資源。接下來,我們需要進一步排查是哪個線程、哪段代碼導致了這種情況。
首先,我們需要下載 Arthas 工具:
curl -L https://arthas.aliyun.com/install.sh | sh
啟動:
./as.sh
使用 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); }}
因此,我們每次執行 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(); } }
通過實現 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 飆高的情況,最終再次解決問題后系統性能有了顯著提升。
因此,這個經歷再次驗證了“事出反常必有妖”,排查問題確實需要有耐心和系統性。
本文鏈接:http://www.www897cc.com/showinfo-26-97280-0.html性能指標 | CPU飆高排查實戰
聲明:本網頁內容旨在傳播知識,若有侵權等問題請及時與本網聯系,我們將在第一時間刪除處理。郵件:2376512515@qq.com
上一篇: 為什么會 Js 但是依然不會寫 Node?原因竟是這三點...
下一篇: 如何獲取請求的進度,并展示給用戶看?