性能指標(biāo) | CPU飆高排查實(shí)戰(zhàn)
問(wèn)題發(fā)現(xiàn)
前段時(shí)間我們新上線了一個(gè)應(yīng)用，由于流量一直不大，集群的每秒查詢率（QPS）大約只有 5。接口的響應(yīng)時(shí)間大約在 30 毫秒左右。
最近我們接入了新的業(yè)務(wù)，業(yè)務(wù)方提供的數(shù)據(jù)顯示，日常的 QPS 預(yù)計(jì)可以達(dá)到 2000，而在大促期間峰值 QPS 可能會(huì)達(dá)到 1 萬(wàn)。
為了評(píng)估系統(tǒng)的性能水平，我們進(jìn)行了一次壓力測(cè)試。測(cè)試在預(yù)發(fā)布環(huán)境進(jìn)行。在壓力測(cè)試過(guò)程中，我們觀察到當(dāng)單臺(tái)服務(wù)器的 QPS 達(dá)到約 200 時(shí)，接口的響應(yīng)時(shí)間沒(méi)有明顯變化，但是 CPU 利用率迅速上升，直到達(dá)到極限。
圖片
壓力測(cè)試結(jié)束后，CPU 利用率立即下降。
隨后我們開(kāi)始排查是什么原因?qū)е铝?CPU 的突然飆升。
排查與解決
在壓力測(cè)試期間，登錄到機(jī)器后，我們開(kāi)始排查問(wèn)題。
本案例的排查過(guò)程使用了阿里開(kāi)源的 Arthas 工具。如果沒(méi)有 Arthas，也可以使用 JDK 自帶的命令進(jìn)行排查。
在開(kāi)始具體排查之前，可以先查看 CPU 的使用情況。最簡(jiǎn)單的方法是使用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可以清楚的看到，進(jìn)程 ID 為 3480 的 Java 進(jìn)程占用了較高的 CPU，可以初步推斷是應(yīng)用代碼執(zhí)行過(guò)程中消耗了大量的 CPU 資源。接下來(lái)，我們需要進(jìn)一步排查是哪個(gè)線程、哪段代碼導(dǎo)致了這種情況。
首先，我們需要下載 Arthas 工具：
curl -L https://arthas.aliyun.com/install.sh | sh啟動(dòng)：
./as.sh使用 Arthas 命令 "thread -n 3 -i 1000"查看當(dāng)前"最忙"（耗 CPU）的三個(gè)線程：
圖片
通過(guò)上述堆棧信息可以看出，占用 CPU 資源的線程主要是在 JDBC 底層的 TCP 套接字讀取上阻塞。經(jīng)過(guò)連續(xù)執(zhí)行多次分析，發(fā)現(xiàn)很多線程都在這個(gè)地方卡住。
進(jìn)一步分析調(diào)用鏈后發(fā)現(xiàn)，這個(gè)問(wèn)題源自于我代碼中的數(shù)據(jù)庫(kù) insert 操作，其中使用了 TDDL 來(lái)創(chuàng)建 sequence。在 sequence 的創(chuàng)建過(guò)程中，需要與數(shù)據(jù)庫(kù)進(jìn)行交互。
根據(jù)對(duì) TDDL 的了解，它每次從數(shù)據(jù)庫(kù)查詢 sequence 序列時(shí)，默認(rèn)會(huì)獲取 1000 條，并在本地進(jìn)行緩存，直到使用完這 1000 條序列之后才會(huì)再次從數(shù)據(jù)庫(kù)獲取下一個(gè) 1000 條序列。
考慮到我們的壓測(cè) QPS 僅約為 300 左右，不應(yīng)該導(dǎo)致如此頻繁的數(shù)據(jù)庫(kù)交互。然而，通過(guò)多次使用 Arthas 進(jìn)行查看，發(fā)現(xiàn)大部分的 CPU 資源都耗費(fèi)在這里。
因此，我們開(kāi)始排查代碼問(wèn)題。最終，發(fā)現(xiàn)了一個(gè)非常簡(jiǎn)單的問(wèn)題，即我們的 sequence 創(chuàng)建和使用存在著明顯的缺陷：
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();
}
/**
* 獲取下一個(gè)主鍵ID
*
* @return
*/
protected Long next() {
try {
return sequence().nextValue();
} catch (SequenceException e) {
throw new RuntimeException(e);
}
}因此，我們每次執(zhí)行 insert 語(yǔ)句時(shí)都重新構(gòu)建了一個(gè)新的 sequence 對(duì)象，這導(dǎo)致本地緩存被清空。因此，每次都需要從數(shù)據(jù)庫(kù)重新獲取 1000 條 sequence，但實(shí)際上只使用了一條，下次又會(huì)重復(fù)這個(gè)過(guò)程。
為了解決這個(gè)問(wèn)題，我們調(diào)整了代碼，在應(yīng)用啟動(dòng)時(shí)初始化了一個(gè) Sequence 實(shí)例。這樣，在后續(xù)獲取 sequence 時(shí)，不會(huì)每次都與數(shù)據(jù)庫(kù)交互。而是首先檢查本地緩存，只有在本地緩存用盡時(shí)才會(huì)再次與數(shù)據(jù)庫(kù)交互，獲取新的 sequence。
public abstract class BaseMybatisDAO implements InitializingBean {
@Override
public void afterPropertiesSet() throws Exception {
sequence = SequenceBuilder.create().name(getTableName()).sequenceDao(sequenceDao).build();
}
}通過(guò)實(shí)現(xiàn) InitializingBean 接口，并重寫(xiě)其中的 afterPropertiesSet()方法，在該方法中進(jìn)行 Sequence 的初始化。
完成以上代碼修改后，提交并進(jìn)行驗(yàn)證。根據(jù)監(jiān)控?cái)?shù)據(jù)顯示，優(yōu)化后數(shù)據(jù)庫(kù)的讀取響應(yīng)時(shí)間（RT）明顯下降。
圖片
sequence 的寫(xiě)操作 QPS 也有明顯下降：
圖片
于是我們開(kāi)始了新的一輪壓測(cè)，但是發(fā)現(xiàn) CPU 的使用率仍然很高，壓測(cè)的 QPS 還是無(wú)法達(dá)到預(yù)期。因此，我們決定重新使用 Arthas 工具查看線程的情況。
圖片
發(fā)現(xiàn)了一個(gè) CPU 消耗較高的線程堆棧，主要是因?yàn)槲覀冊(cè)谑褂靡粋€(gè)聯(lián)調(diào)工具時(shí)，該工具預(yù)發(fā)布狀態(tài)下默認(rèn)開(kāi)啟了 TDDL 的日志采集（盡管官方文檔中描述預(yù)發(fā)布狀態(tài)下默認(rèn)不會(huì)開(kāi)啟 TDDL 采集，但實(shí)際上確實(shí)會(huì)進(jìn)行采集）。
在該工具打印日志時(shí)，會(huì)進(jìn)行數(shù)據(jù)脫敏操作，脫敏框架使用了 Google 的 re2j 進(jìn)行正則表達(dá)式匹配。
由于我的操作涉及到大量的 TDDL 操作，而默認(rèn)情況下會(huì)采集大量 TDDL 日志并進(jìn)行脫敏處理，這導(dǎo)致了較高的 CPU 消耗。
因此，通過(guò)在預(yù)發(fā)布環(huán)境中關(guān)閉對(duì) TDDL 的日志采集，可以有效解決這個(gè)問(wèn)題。
總結(jié)
這篇總結(jié)回顧了一次線上 CPU 飆高問(wèn)題的排查過(guò)程，雖然問(wèn)題最終解決起來(lái)并不復(fù)雜，但排查過(guò)程中卻有其獨(dú)特的教育意義。
之前經(jīng)驗(yàn)豐富的我按照慣例進(jìn)行了排查，初始階段并未發(fā)現(xiàn)明顯問(wèn)題，錯(cuò)誤地將數(shù)據(jù)庫(kù)操作增加歸因于流量上升所致的正常情況。
通過(guò)多方查證（例如使用 arthas 查看序列獲取情況，以及通過(guò)數(shù)據(jù)庫(kù)查詢最新插入數(shù)據(jù)的主鍵 ID 等方法），最終確認(rèn)問(wèn)題出在 TDDL 的序列初始化機(jī)制上。
解決了這個(gè)問(wèn)題后，本以為問(wèn)題徹底解決，卻又遭遇到 DP 采集 TDDL 日志導(dǎo)致 CPU 飆高的情況，最終再次解決問(wèn)題后系統(tǒng)性能有了顯著提升。
因此，這個(gè)經(jīng)歷再次驗(yàn)證了“事出反常必有妖”，排查問(wèn)題確實(shí)需要有耐心和系統(tǒng)性。
