△Hollis, 一個對Coding有著獨(dú)特追求的人△這是Hollis的第 344 篇原創(chuàng)分享來源 l Hollis（ID：hollischuang）前段時間我們新上了一個新的應(yīng)用，因?yàn)榱髁恳恢辈淮?，集群QPS大概只有5左右，寫接口的rt在30ms左右。
因?yàn)樽罱尤肓诵碌臉I(yè)務(wù)，業(yè)務(wù)方給出的數(shù)據(jù)是日常QPS可以達(dá)到2000，大促峰值QPS可能會達(dá)到1萬。所以，為了評估水位，我們進(jìn)行了一次壓測。壓測過程中發(fā)現(xiàn)，當(dāng)單機(jī)QPS達(dá)到200左右時，接口的rt沒有明顯變化，但是CPU利用率急劇升高，直到被打滿。
本案例的排查過程使用的阿里開源的Arthas工具進(jìn)行的，不使用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
可以看到，進(jìn)程ID為3480的Java進(jìn)程占用的CPU比較高，基本可以斷定是應(yīng)用代碼執(zhí)行過程中消耗了大量CPU，接下來開始排查具體是哪個線程，哪段代碼比較耗CPU。curl -L http://start.alibaba-inc.com/install.sh | sh
./as.sh
使用Arthas命令"thread -n 3 -i 1000"查看當(dāng)前"最忙"（耗CPU）的三個線程：
通過上面的堆棧信息，可以看出，占用CPU資源的線程主要是卡在JDBC底層的TCP套接字讀取上。連續(xù)執(zhí)行了很多次，發(fā)現(xiàn)很多線程都是卡在這個地方。通過分析調(diào)用鏈，發(fā)現(xiàn)這個地方是我代碼中有數(shù)據(jù)庫的insert，并且使用TDDL（阿里內(nèi)部的分布式數(shù)據(jù)庫中間件）來創(chuàng)建sequence，在sequence的創(chuàng)建過程中需要和數(shù)據(jù)庫有交互。但是，基于對TDDL的了解，TDDL每次從數(shù)據(jù)庫中查詢sequence序列的時候，默認(rèn)會取出1000條，緩存在本地，只有用完之后才會再從數(shù)據(jù)庫獲取下一個1000條序列。按理說我們的壓測QPS只有300左右，不應(yīng)該這么頻繁的何數(shù)據(jù)庫交互才對。但是，經(jīng)過多次使用Arthas的查看，發(fā)現(xiàn)大部分CPU都耗盡在這里。于是開始排查代碼問題。最終發(fā)現(xià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();
}
/**
* 獲取下一個主鍵ID
*
* @return
*/
protected Long next() {
try {
return sequence().nextValue();
} catch (SequenceException e) {
throw new RuntimeException(e);
}
}
是因?yàn)椋?strong>我們每次insert語句都重新build了一個新的sequence，這就導(dǎo)致本地緩存就被丟掉了，所以每次都會去數(shù)據(jù)庫中重新拉取1000條，但是只是用了一條，下一次就又重新取了1000條，周而復(fù)始。于是，調(diào)整了代碼，把Sequence實(shí)例的生成改為在應(yīng)用啟動時初始化一次。這樣后面在獲取sequence的時候，不會每次都和數(shù)據(jù)庫交互，而是先查本地緩存，本地緩存的耗盡了才會再和數(shù)據(jù)庫交互，獲取新的sequence。public abstract class BaseMybatisDAO implements InitializingBean {
@Override
public void afterPropertiesSet() throws Exception {
sequence = SequenceBuilder.create().name(getTableName()).sequenceDao(sequenceDao).build();
}
}
通過實(shí)現(xiàn)InitializingBean，并且重寫afterPropertiesSet()方法，在這個方法中進(jìn)行Sequence的初始化。改完以上代碼，提交進(jìn)行驗(yàn)證。通過監(jiān)控數(shù)據(jù)可以看出優(yōu)化后，數(shù)據(jù)庫的讀RT有明顯下降：
于是我們開始了新的一輪壓測，但是發(fā)現(xiàn)，CPU的使用率還是很高，壓測的QPS還是上不去，于是重新使用Arthas查看線程的情況。
發(fā)現(xiàn)了一個新的比較耗費(fèi)CPU的線程的堆棧，這里面主要是因?yàn)槲覀冇玫搅艘粋€聯(lián)調(diào)工具，該工具預(yù)發(fā)布默認(rèn)開啟了TDDL的采集（官方文檔中描述為預(yù)發(fā)布默認(rèn)不開啟TDDL采集，但是實(shí)際上會采集）。這個工具在打印日志過程中會進(jìn)行脫敏，脫敏框架會調(diào)用Google的re2j進(jìn)行正則表達(dá)式的匹配。因?yàn)槲业牟僮髦蠺DDL操作比較多，默認(rèn)采集大量TDDL日志并且進(jìn)行脫敏處理，確實(shí)比較耗費(fèi)CPU。所以，通過在預(yù)發(fā)布中關(guān)閉DP對TDDL的采集，即可解決該問題。本文總結(jié)了一次線上CPU飆高的問題排查過程，其實(shí)問題都不難，并且還挺傻的，但是這個排查過程是值得大家學(xué)習(xí)的。其實(shí)在之前自己排查過很多次CPU飆高的問題，這次也是按照老方法進(jìn)行排查，但是剛開始并沒有發(fā)現(xiàn)太大的問題，只是以為是流量升高導(dǎo)致數(shù)據(jù)庫操作變多的正常現(xiàn)象。期間又多方查證（通過Arthas查看sequence的獲取內(nèi)容、通過數(shù)據(jù)庫查看最近插入的數(shù)據(jù)的主鍵ID等）才發(fā)現(xiàn)是TDDL的Sequence的初始化機(jī)制有問題。在解決了這個問題之后，以為徹底解決問題，結(jié)果又遇到了DP采集TDDL日志導(dǎo)致CPU飆高，最終再次解決后有了明顯提升。所以，事出反常必有妖，排查問題就是一個抽絲剝繭的過程。
