本文結(jié)合一個實際故障案例出發(fā)，從小白的視角分析慢SQL是如何打垮數(shù)據(jù)庫并引發(fā)故障的。

一、案發(fā)現(xiàn)場

上午9:49，應用報警：4103.ERR_ATOM_CONNECTION_POOL_FULL，應用數(shù)據(jù)庫連接池滿。

上午9:49-10:08期間，陸續(xù)出現(xiàn) 4200.ERR_GROUP_NOT_AVALILABLE、4201.ERR_GROUP_NO_ATOM_AVAILABLE、4202.ERR_SQL_QUERY_TIMEOUT等數(shù)據(jù)庫異常報警。

由于數(shù)據(jù)庫承載了銷售核心的用戶組織權(quán)限功能，故障期間，期間銷售工作臺無法打開，大量小二反饋咨詢。

上午10:08，定位到有應用基礎緩存包升級發(fā)布，上午9點40剛完成最后一批發(fā)布，時間點相吻合，嘗試通過打開緩存開關(guān)，系統(tǒng)恢復。

二、現(xiàn)場結(jié)論

對此次升級緩存包應用發(fā)布內(nèi)容分析，發(fā)現(xiàn)升級的某個二方包中，刪除了本地緩存邏輯，直接請求DB，而本次升級沒有對請求的SQL進行優(yōu)化，如下代碼所示，該SQL從Oracle遷移到MySQL，由于數(shù)據(jù)庫性能的差異，最終造成慢查詢，平均一次執(zhí)行2S多，大量慢SQL最終打掛數(shù)據(jù)庫。

注：1 ?SELECT CRM_USER_ID AS LOGIN_ID, CRM_ROLE_ID AS ROLE_NAME, CRM_ORG_ID AS ORG

經(jīng)過討論排查分析，得出以下結(jié)論：

1. 之前邏輯走本地內(nèi)存，本次升級中由于涉及到的某個二方庫代碼變更刪除了本地邏輯改查DB。

2. 查詢DB的SQL去O階段沒有進行優(yōu)化，在MySQL下為慢SQL，大量慢SQL查詢拖垮了數(shù)據(jù)庫。

三、進一步的疑問

面對上述結(jié)論，作為數(shù)據(jù)庫方面的小白，有以下幾個疑問，感覺需要深入挖掘：

1. 這條SQL為何是慢SQL；

2. 發(fā)布的應用為非核心應用，只是與登錄權(quán)限共用了一個數(shù)據(jù)庫，當時發(fā)布應用的QPS只有0.幾，為何可以把庫打掛；

3. 之前已經(jīng)申請過一波連接池擴容，從10擴到了15，發(fā)布的應用線上有流量的機器不過7臺，為何可以把數(shù)據(jù)庫壓垮；

4. 事后復盤，發(fā)布前一天灰度時也有過慢SQL，為何當時沒有壓垮數(shù)據(jù)庫；

四、深入分析原理

帶著以上疑問，結(jié)合以下相關(guān)知識，一層層剝開深層次的原因

4.1、慢SQL分析

CONCAT(CRM_ORG_ID, '#', CRM_ROLE_ID) = '123#abc'?

該SQL由工具直接從Oracle翻譯過來的

• 雖然兩個拼接的字段各自都有索引，但是使用函數(shù)后，MySQL是不會使用索引的，退化為了普通查詢

• 由于表數(shù)據(jù)量較大，全表40W+數(shù)據(jù)，導致掃描行數(shù)很多，平均掃描16W行、邏輯讀38W行，執(zhí)行2s左右

4.2、業(yè)務代碼排查

• 故障后第二天，有個別銷售反饋頁面打開較慢，有好幾秒，懷疑是止血時的操作是切到了tair而不是回滾到本地緩存邏輯導致，不過此時還是有疑問，為何一個頁面會慢好幾秒呢，聽起來就像是一次請求大量循環(huán)調(diào)用緩存導致；

• 代理賬號經(jīng)定位，確實是如上假設，此處的業(yè)務代碼邏輯為查找組織下的指定角色，會遞歸遍歷所有子組織，最差情況下，一次頁面請求，會有1000+次訪問緩存/DB；

• 結(jié)合數(shù)據(jù)庫當時慢SQL趨勢，符合我們的猜測，雖然業(yè)務流量不大，但是每次請求會放大1000倍，最終導致問題SQL執(zhí)行了1.5W+次，同時同下圖可以看到，其他正常SQL由于系統(tǒng)忙被排隊，響應也變慢，而這些基本都是基礎用戶組織權(quán)限相關(guān)，所以造成了業(yè)務系統(tǒng)不可用；

4.3、druid連接池？數(shù)據(jù)庫連接池？

• 上文背景處有說道，應用連接池配置的為15，切應用流量本身很小，那么是什么原因?qū)е抡麄€庫都被拖垮呢；

• 這里要從一次SQL請求的鏈路說起，如下圖所示：

• 應用層通過tddl訪問MySQL數(shù)據(jù)源，其中連接管理是在atom層，利用druid進行連接池的管理，我們平時所說的tddl線程池，指的就是druid連接池，這個配置維護在diamond中，一般有dba來設置；

• 對于我們的應用來說，單個應用7臺機器，maxPoolSize配置為15，數(shù)據(jù)庫是單庫單表，則單個應用的最大連接數(shù)為1*15，所有應用連接數(shù)為7*1*15=105；

• 注意以上只是應用維度的連接數(shù)推導，正常工作下連接池也不會達到max的，如果達到了，TDDL會拋出4103.ERR_ATOM_CONNECTION_POOL_FULL，應用數(shù)據(jù)庫連接池滿錯誤，與第一節(jié)現(xiàn)象吻合；

• 那么問題來了，這么幾個連接，為何打垮整個數(shù)據(jù)庫呢；看數(shù)據(jù)庫的最大連接數(shù)可是有8000；

• 經(jīng)與DBA同學咨詢，了解到了數(shù)據(jù)庫server端的內(nèi)部處理線程池與druid沒有任何關(guān)系，兩者是兩個層面的東西，所以需要研究下server端的處理邏輯；

• 同時這里提一點，由于我們很多應用都在連接數(shù)據(jù)庫，所以需要評估下數(shù)據(jù)庫的最大連接數(shù)是否可以滿足這么多應用的機器的鏈接，即應用服務器總數(shù) * 一個數(shù)據(jù)庫實例上的分庫數(shù)(atom) * maxPoolSize < max_user_connections；

4.4、MySQL數(shù)據(jù)庫性能分析

• 如上圖所示，案發(fā)時，有一個明顯的現(xiàn)象，數(shù)據(jù)庫CPU被打滿，同時活躍連接數(shù)增長、數(shù)據(jù)庫rt增長：

• 活躍連接數(shù)，當前數(shù)據(jù)庫中有多少會話正在執(zhí)行SQL，是衡量數(shù)據(jù)庫繁忙程度的指標；

• 根據(jù)執(zhí)行時間來判斷，閾值一般很低，正常情況下一條SQL執(zhí)行很快，活躍會話很低；

• 經(jīng)過與DBA同學請教，結(jié)合慢SQL明細，確定問題就是慢SQL執(zhí)行，大量邏輯讀導致的；

• server端的鏈路還原如下：

• 針對數(shù)據(jù)庫實例，出于保護，引入了線程池，通過參數(shù)進行控制，默認300個左右；

• 正常情況下，由于SQL執(zhí)行很快，活躍會話不會很高；

• 慢SQL情況下，由于每一條慢SQL都會邏輯讀30W+行，執(zhí)行2s+，導致線程變慢，線程池里的線程被用盡，也即活躍會話數(shù)上升，如上圖所示，逼近280；

• 數(shù)據(jù)庫CPU都在執(zhí)行慢SQL的邏輯讀和排序等操作、活躍會話數(shù)大幅增長，數(shù)據(jù)庫rt飆升，導致其他應用請求無法與數(shù)據(jù)庫建立新的會話，應用請求超時，TDDL層進入fast fail狀態(tài)，拋出4201.ERR_GROUP_NO_ATOM_AVAILABLE異常；

4.5、慢SQL是如何導致CPU打滿的

• 上面分析中，有一個核心的細節(jié)，就是慢SQL邏輯讀太多，最終導致CPU打滿了，這里有個疑問，讀寫不是io操作嗎，為什么會使CPU load高呢，研究了一下innodb的結(jié)構(gòu)：

• 如下圖所示，在innodb存儲層，維護了一個緩存數(shù)據(jù)和索引信息到內(nèi)存的存儲區(qū)叫做buffer pool，他會將最近訪問的數(shù)據(jù)緩存到緩沖區(qū)；

• 我們說的邏輯讀：也就是SQL在同一時間內(nèi)需要訪問多少個緩沖區(qū)的內(nèi)存頁；

• 而與之相對應的，物理讀則是同一時間內(nèi)需要從磁盤獲取多少個數(shù)據(jù)塊；

• 理想情況下，buffer pool size應該設置的盡可能大，這樣就可以減少進程的額外分頁，當buffer pool size設置的足夠大的時候，整個數(shù)據(jù)庫就相當于存儲在內(nèi)存當中，當讀取一次數(shù)據(jù)到buffer pool size以后，后續(xù)的讀操作就不用在進行磁盤讀；

• 通過現(xiàn)場的cloud dba監(jiān)控也可以發(fā)現(xiàn)，innoDB緩存命中率為100%，不存在物理讀的情況，也即可以認為數(shù)據(jù)庫的高頻數(shù)據(jù)都已全量存在于內(nèi)存中了，通過查看數(shù)據(jù)庫容量也可以佐證這個觀點，數(shù)據(jù)+索引大小6G左右，未達到數(shù)據(jù)庫實例配置的8G，所以實際情況是數(shù)據(jù)都存在于內(nèi)存中了，并不會有多余的IO操作，CPU的性能全部都消耗在了大量的內(nèi)存數(shù)據(jù)掃表(邏輯讀)中 - 看現(xiàn)場平均掃描16w行數(shù)據(jù)；

• 這個結(jié)論讓我不禁想到了一個類似的場景，在線上vi打開服務器中大文件導致load飆高，應用不可用的問題。vi在將文件原樣加載到內(nèi)存后，還會將其轉(zhuǎn)換為內(nèi)部結(jié)構(gòu)（線條，單詞等），使用內(nèi)部腳本語言執(zhí)行語法高亮顯示等等，所有這些都會消耗內(nèi)存和CPU時間。

• 雖然慢SQL模板只一個，QPS也不是特別高(現(xiàn)場峰值100左右，平均20左右)，但是由于線程池機制，快速將活躍會話(線程池)占滿；

• 由于業(yè)務QPS水位在3000左右，線程池打滿后，后續(xù)即使是索引甚至是主鍵查詢的正常SQL，也都在排隊了，最終導致了雪崩效應；

4.6、關(guān)于數(shù)據(jù)庫升配

• 在優(yōu)化慢SQL的同時，考慮到數(shù)據(jù)庫實例配置較低(8core 8G 100G)，也嘗試與DBA相關(guān)同學溝通升級配置，經(jīng)過多次討論，結(jié)論為升配無用，只能優(yōu)化慢SQL或者加緩存，以下配置核心的三個維度進行說明；

• CPU：目前實例配置為8核，但是MySQL集群的CPU隔離是放開的，最高可用到物理機的64核，所以無需升配；

• 內(nèi)存：目前實例配置為8G，內(nèi)存這塊直接影響的就是上述介紹的buffer pool，如4.5小結(jié)分析，庫總數(shù)據(jù)量都沒有達到8G，所以無需進行內(nèi)存升級；

• 磁盤：目前實例配置為100G，以目前業(yè)務發(fā)展速度也已夠用；

五、總結(jié)

• 直接原因：應用升級二方庫中本地緩存代碼被刪除；慢SQL沒有優(yōu)化；同時業(yè)務邏輯復雜，嵌套循環(huán)導致快速雪崩；

• 根本原因：慢SQL導致數(shù)據(jù)庫CPU打滿，活躍連接數(shù)突增，rt上升，后續(xù)SQL請求都在排隊，高QPS場景下，最終導致雪崩效應，TDDL fast fail，拋出數(shù)據(jù)庫不可用異常；

• 兩個池的知識點：TDDL中的druid插件維護的是業(yè)務應用層與數(shù)據(jù)庫連接的連接池；MySQL服務端 也會通過線程池技術(shù)，處理會話，默認300左右，一般情況下SQL執(zhí)行非?？?，所以活躍線程/活躍會話非常低；

• 快速定位數(shù)據(jù)庫問題的思路 -- 熟練掌握cloud dba的性能分析工具：

• 判斷數(shù)據(jù)庫是否正常：RT - 響應時間是否變大了；活躍會話 - 數(shù)據(jù)庫當前是否擁堵了；

• QPS：是否有突發(fā)大流量；

• 檢查執(zhí)行的SQL：如果邏輯讀、DML大幅增長，則基本可以鎖定該SQL出了問題。

參考資料：

關(guān)于MySQL線程池，這也許是目前最全面的實用帖?。篽ttps://dbaplus.cn/news-11-1989-1.html

當我有16 GB RAM時，為什么Vim無法打開100 MB文本文件？：https://qastack.cn/unix/139254/why-cant-vim-open-a-100-mb-text-file-when-i-have-16-gb-ram