你要偷偷學會排查線上CPU飆高的問題，然後驚豔所有人！
阿新 • • 發佈：2021-03-31
[GitHub 20k Star 的Java工程師成神之路，不來了解一下嗎！](https://github.com/hollischuang/toBeTopJavaer)
[GitHub 20k Star 的Java工程師成神之路，真的不來了解一下嗎！](https://github.com/hollischuang/toBeTopJavaer)
[GitHub 20k Star 的Java工程師成神之路，真的真的不來了解一下嗎！](https://github.com/hollischuang/toBeTopJavaer)
前段時間我們新上了一個新的應用，因為流量一直不大，叢集QPS大概只有5左右，寫介面的rt在30ms左右。
因為最近接入了新的業務，業務方給出的資料是日常QPS可以達到2000，大促峰值QPS可能會達到1萬。
所以，為了評估水位，我們進行了一次壓測。壓測在預釋出環境執行。壓測過程中發現，當單機QPS達到200左右時，介面的rt沒有明顯變化，但是CPU利用率急劇升高，直到被打滿。
![-w1460][1]
壓測停止後，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
可以看到，程序ID為3480的Java程序佔用的CPU比較高，基本可以斷定是應用程式碼執行過程中消耗了大量CPU，接下來開始排查具體是哪個執行緒，哪段程式碼比較耗CPU。
首先，下載Arthas命令：
curl -L http://start.alibaba-inc.com/install.sh | sh
啟動
./as.sh
使用Arthas命令"thread -n 3 -i 1000"檢視當前"最忙"（耗CPU）的三個執行緒：
![-w1147][2]
通過上面的堆疊資訊，可以看出，佔用CPU資源的執行緒主要是卡在JDBC底層的TCP套接字讀取上。連續執行了很多次，發現很多執行緒都是卡在這個地方。
通過分析呼叫鏈，發現這個地方是我程式碼中有資料庫的insert，並且使用TDDL來建立sequence，在sequence的建立過程中需要和資料庫有互動。
但是，基於對TDDL的瞭解，TDDL每次從資料庫中查詢sequence序列的時候，預設會取出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語句都重新build了一個新的sequence，這就導致本地快取就被丟掉了，所以每次都會去資料庫中重新拉取1000條，但是隻是用了一條，下一次就又重新取了1000條，周而復始。
於是，調整了程式碼，把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有明顯下降：
![][3]
sequence的寫操作QPS也有明顯下降：
![][4]
於是我們開始了新的一輪壓測，但是發現，CPU的使用率還是很高，壓測的QPS還是上不去，於是重新使用Arthas檢視執行緒的情況。
![][5]
發現了一個新的比較耗費CPU的執行緒的堆疊，這裡面主要是因為我們用到了一個聯調工具，該工具預釋出預設開啟了TDDL的採集（官方文件中描述為預釋出預設不開啟TDDL採集，但是實際上會採集）。
這個工具在列印日誌過程中會進行脫敏，脫敏框架會呼叫Google的re2j進行正則表示式的匹配。
因為我的操作中TDDL操作比較多，預設採集大量TDDL日誌並且進行脫敏處理，確實比較耗費CPU。
所以，通過在預釋出中關閉DP對TDDL的採集，即可解決該問題。
### 總結與思考
本文總結了一次線上CPU飆高的問題排查過程，其實問題都不難，並且還挺傻的，但是這個排查過程是值得大家學習的。
其實在之前自己排查過很多次CPU飆高的問題，這次也是按照老方法進行排查，但是剛開始並沒有發現太大的問題，只是以為是流量升高導致資料庫操作變多的正常現象。
期間又多方查證（通過arthas檢視sequence的獲取內容、通過資料庫檢視最近插入的資料的主鍵ID等）才發現是TDDL的Sequence的初始化機制有問題。
在解決了這個問題之後，以為徹底解決問題，結果又遇到了DP採集TDDL日誌導致CPU飆高，最終再次解決後有了明顯提升。
所以，事出反常必有妖，排查問題就是一個抽絲剝繭的過程。
關於作者：[Hollis](https://shimo.im/docs/vFsWCtTFIlQav7UC/read)，一個對Coding有著獨特追求的人，阿里巴巴技術專家，《程式設計師的三門課》聯合作者，《Java工程師成神之路》系列文章作者。
如果您有任何意見、建議，或者想與作者交流，都可以關注公眾號【[Hollis](https://shimo.im/docs/vFsWCtTFIlQav7UC/read)】，直接後臺給我留言。
[1]: https://www.hollischuang.com/wp-content/uploads/2021/03/16165515783925-scaled.jpg
[2]: https://www.hollischuang.com/wp-content/uploads/2021/03/16165659820207.jpg
[3]: https://www.hollischuang.com/wp-content/uploads/2021/03/16165777571485.jpg
[4]: https://www.hollischuang.com/wp-content/uploads/2021/03/16165777883205.jpg
[5]: https://www.hollischuang.com/wp-content/uploads/2021/03/16165667534840.jpg