壓力測試過程中MySQL服務CPU占用率過高的問題排查思路

〇、經(jīng)驗總結(jié)：

• 在關注業(yè)務接口的TPS時，也要關注數(shù)據(jù)庫服務器的QPS。如果一個業(yè)務流程里包含多條查詢，那么業(yè)務接口TPS的上升對數(shù)據(jù)庫服務器QPS的放大效應會很明顯。
• 如果查詢結(jié)果集不大，盡量使用一條查詢語句，通過子查詢返回多個結(jié)果集，避免將多個結(jié)果集拆分成多次數(shù)據(jù)庫查詢，否則會造成過多的數(shù)據(jù)庫連接/查詢操作，消耗IO資源，降低TPS，提高CPU占用率。
• 在業(yè)務代碼中，盡量避免在循環(huán)語句里寫數(shù)據(jù)庫查詢。
• 依據(jù)SQL語句的使用頻率來建立索引，查詢條件字段順序按照聯(lián)合索引的字段順序來寫（從左到右的匹配順序）
• 關注慢查日志

一、背景說明

接著上一篇Grpc性能調(diào)優(yōu)的文章繼續(xù)寫，我們這次壓測的是一個查詢用戶群組列表信息的接口，該接口里需要查詢某個用戶的所有群組信息，包括每個群組的名稱、成員數(shù)量等。
經(jīng)過之前對業(yè)務機器的JVM參數(shù)等進行優(yōu)化后，現(xiàn)在已經(jīng)不存在業(yè)務機器的頻繁GC、CPU占用率過高、TPS上不去等問題了。但是我們遇到了兩個新問題：在業(yè)務接口并發(fā)50、TPS600左右時，壓測接口出現(xiàn)了超時錯誤，而且數(shù)據(jù)庫服務器CPU占用率超過了93%！

二、測試過程

數(shù)據(jù)準備：

• t_info_group群組表：
  

• t_info_group_member群組成員表：
  

數(shù)據(jù)約定：測試數(shù)據(jù)中，每個群組里面有3000個成員；每個成員有20個群組。

1、第一次壓測

我們首先進行一次摸底測試，使用兩臺壓測機器共同發(fā)起300個并發(fā)，持續(xù)壓測2分鐘。（如果只用一臺壓測機發(fā)起300個并發(fā)，會由于機器端口受限，TPS超過5W后不能發(fā)起新請求，壓測機將報錯）
（1）數(shù)據(jù)庫連接池配置
c3p0.initialPoolSize=15
c3p0.minPoolSize=15
c3p0.acquireIncrement=10
c3p0.maxPoolSize=32
（2）數(shù)據(jù)庫慢查日志、數(shù)據(jù)庫服務器監(jiān)控指標

top命令顯示CPU使用率超過了91%，而且慢查日志一直在刷！
通過分析慢查日志里面的SQL語句，以及對應的數(shù)據(jù)庫表，發(fā)現(xiàn)查詢語句中有“where a=.. and b=.. and c=..”，但是有一個聯(lián)合索引的字段是“a, c"。根據(jù)聯(lián)合索引的匹配規(guī)則，這條sql用不了索引，導致慢查。經(jīng)過將索引更換成"a, b, c"，單條sql查詢效率提高一倍。

2、第二次壓測

使用兩臺壓測機器共同發(fā)起50個并發(fā)，持續(xù)壓測2分鐘。
（1）其他配置均不做改變。
（2）數(shù)據(jù)庫慢查日志、數(shù)據(jù)庫服務器監(jiān)控指標
經(jīng)過上述調(diào)整，慢查日志沒有了，但是CPU使用率依然還是超過了90%。這是一個不能容忍的數(shù)據(jù)，如果并發(fā)繼續(xù)提高，數(shù)據(jù)庫服務器很快將被撐爆。

由于其他涉及到sql查詢的接口在壓測時都沒有出現(xiàn)過CPU占用率這么高的情況，所以我們排除了數(shù)據(jù)庫服務器安裝配置的問題。
我們開始思考出現(xiàn)問題的可能原因：

• 數(shù)據(jù)庫連接池等參數(shù)配置有缺陷，導致連接池不夠用，一直在建立新的連接。
• 業(yè)務代碼邏輯可能存在缺陷，導致查詢語句消耗過多IO或內(nèi)存資源。
• 并發(fā)數(shù)量高，數(shù)據(jù)庫服務器CPU正常就需要占用這么多。（這是最無奈最不想接受的結(jié)局）
  我們先查看show processlist; 的結(jié)果，發(fā)現(xiàn)有很多連接其實是空閑的，也就是說目前的連接池已經(jīng)夠用了。
  而當我們把連接池嘗試放大，配置改為：
  c3p0.initialPoolSize=20
  c3p0.minPoolSize=20
  c3p0.acquireIncrement=20
  c3p0.maxPoolSize=128
  在這個配置下，對CPU的占用率沒有絲毫影響。那么排除連接池配置的問題。
  那有沒有可能是在當前并發(fā)量條件下，就需要消耗這么多的CPU呢？
  我們對比了另一個涉及到SQL查詢的接口，在60個并發(fā)下，那個接口的TPS達到了1100，而現(xiàn)在壓測的接口，TPS只有600。那么在同等并發(fā)下，相同的查詢語句復雜度和查詢結(jié)果數(shù)據(jù)量條件下，現(xiàn)在壓測的接口不僅TPS低，還占用了過多的CPU，可能就不是數(shù)據(jù)庫的問題。這就排除了因并發(fā)量高而必然導致CPU占用率超過90%的假設。
  我們繼續(xù)看數(shù)據(jù)庫服務器的監(jiān)控指標，使用阿里的orzdba腳本監(jiān)控MySQL服務器。
  當前壓測接口的MySQL服務器指標數(shù)據(jù)：
  

對照接口的指標數(shù)據(jù)：

從上述兩個對比圖可以看到，當前壓測接口的數(shù)據(jù)庫QPS高達3000。對比數(shù)據(jù)匯總一下，可以看出一些問題：
當前接口：
并發(fā)：60，TPS：600，數(shù)據(jù)庫CPU：92%，數(shù)據(jù)庫QPS：3000
對照接口：
并發(fā)60，TPS：1000，數(shù)據(jù)庫CPU：20%，數(shù)據(jù)庫QPS：1400
當前壓測接口處理更耗時，可能原因是一次接口業(yè)務里涉及到了多次數(shù)據(jù)庫操作。
那么接下來就是排查業(yè)務代碼里的數(shù)據(jù)庫操作了。進行code review！
核心業(yè)務偽代碼：
//查詢用戶的群組列表
List<Dto> groupList = groupDao.selectGroups(userId);
for(Dto dto:groupList){
//查詢每個群組的用戶數(shù)，會循環(huán)20次！
int userNumber = groupDao.getGroupNumber(dto.getAsIong(groupId));
}

這段代碼怎么這么別扭？第一個查詢已經(jīng)去查詢?nèi)航M信息了，還要用for循環(huán)去遍歷20次統(tǒng)計每個群組用戶數(shù)？？
這樣操作的話，一次接口請求將操作很多次的數(shù)據(jù)庫查詢，并帶來更多網(wǎng)絡、IO操作。那么CPU占用率過高的問題很可能是這個情況導致的。
我們的優(yōu)化措施是優(yōu)化groupDao.selectGroups(userId)對應的查詢語句，使用子查詢返回用戶的群組列表和每個群組的用戶數(shù)，去掉for循環(huán)。

3、第三次壓測

使用兩臺壓測機器共同發(fā)起50個并發(fā)，持續(xù)壓測2分鐘。
（1）其他配置均不做改變。
（2）數(shù)據(jù)庫慢查日志、數(shù)據(jù)庫服務器監(jiān)控指標
數(shù)據(jù)庫慢查日志沒有提示慢查SQL語句，數(shù)據(jù)庫服務器CPU占用率穩(wěn)定在80%以下，數(shù)據(jù)庫QPS提高到了近7000！這個優(yōu)化效果可以說是非常的明顯了。

4、留給我的疑問

也許有人會問：代碼優(yōu)化后數(shù)據(jù)庫的QPS比之前更高了，那CPU使用應該更多啊，但是為什么數(shù)據(jù)庫的CPU占用率反而降下來了呢？這是為什么呢？[這個問題，其實我也沒有想明白，有知道原因的朋友歡迎留言討論。]
對于這個問題，我最近一直在思考，并查閱相關的資料，突然從接口優(yōu)化前后的性能數(shù)據(jù)上可以看到：優(yōu)化前，業(yè)務接口的TPS才600，數(shù)據(jù)庫QPS才3000，而優(yōu)化后的業(yè)務接口TPS達到了1100，幾乎翻倍，同時數(shù)據(jù)庫QPS達到了6000，也翻倍了，但數(shù)據(jù)庫CPU使用率反而降低了。從這幾個數(shù)據(jù)可以得到這樣一條結(jié)論：接口TPS的增長，自然導致了數(shù)據(jù)庫QPS的同級別增長，說明在優(yōu)化前和優(yōu)化后，數(shù)據(jù)庫的壓力瓶頸還遠沒有達到，那么數(shù)據(jù)庫服務器CPU使用率的飆高，也不是由于SQL處理導致的！
數(shù)據(jù)庫服務器的資源消耗，除了SQL執(zhí)行、磁盤IO，其實還有網(wǎng)絡連接。
優(yōu)化前的代碼里，一次TPS會進行多次數(shù)據(jù)庫連接并提交SQL查詢請求，這個操作帶來的網(wǎng)絡連接消耗也是非?？捎^的，優(yōu)化后的代碼里，一次TPS就進行一次數(shù)據(jù)庫連接并提交SQL查詢請求，資源消耗降低了很多。

• 接口優(yōu)化前：
  并發(fā)：60，TPS：600，數(shù)據(jù)庫CPU：92%，數(shù)據(jù)庫QPS：3000
  
  

• 接口優(yōu)化后：
  并發(fā)：60，TPS：1100，數(shù)據(jù)庫CPU：低于80%，數(shù)據(jù)庫QPS：6000