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

〇、經驗總結：

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

一、背景說明

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

二、測試過程

數據準備：

• t_info_group群組表：
  

• t_info_group_member群組成員表：
  

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

1、第一次壓測

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

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

2、第二次壓測

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

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

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

對照接口的指標數據：

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

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

3、第三次壓測

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

4、留給我的疑問

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

• 接口優化前：
  并發：60，TPS：600，數據庫CPU：92%，數據庫QPS：3000
  
  

• 接口優化后：
  并發：60，TPS：1100，數據庫CPU：低于80%，數據庫QPS：6000