前幾天一個客戶資料庫主執行個體告警，診斷過程中發現是由一個慢sql導緻的資料庫故障，而在排查逐漸深入之後卻發現這個現象的不可思議。
2016年12日09日，大概9點26分左右，一個客戶的生産庫主執行個體發出告警，告警資訊如下：
mysql執行個體超過五分鐘沒有更新。這個告警資訊簡單解釋下就是持續五分鐘無法擷取該執行個體的資訊。
同時開發人員還反映，從12月09日淩晨1點開始，已經出現一些資料庫請求逾時的現象，直到出現告警資訊之後業務恢複正常。
該資料庫系統使用袋鼠雲easydb進行性能監控以及告警，easydb服務端無法擷取agent方的資訊，那麼首要任務，就是檢查easydb agent是否存活。
從上圖可見，easydb程序工作正常。那麼接下來就要從資料庫以及伺服器層面去排查
先看下mysql error日志有沒有報錯資訊的記錄。登陸主機，首先了解mysql的安裝情況：
[root@xxxxxx ~]# ps -ef|grep mysqld|egrep -v mysqld_safe
...
/home/my3304/bin/mysqld --defaults-file=/home/my3304/my.cnf --basedir=/home/my3304 --datadir=/home/my3304/data --plugin-dir=/home/my3304/lib/plugin --log-error=/home/my3304/log/alert.log --open-files-limit=65535 --pid-file=/home/my3304/run/mysqld.pid --socket=/home/my3304/run/mysql.sock --port=3304
通過檢視程序狀态資訊，我們可以看到本地啟動的mysql執行個體和mysql的一些配置資訊，可以找到日志存放路徑。
檢視了伺服器上告警執行個體的mysql error log，發現12月09日上午09點16分開始出現大量這樣的報錯，一直持續到09點48分
簡單分析一下報錯資訊的含義：
[root@xxxxxx bin]# ./perror 11
os error code 11: resource temporarily unavailable
報錯的資訊大緻意思是，資源暫時不可用，那麼這個資源指的是什麼？就是thread。從這裡可以看出，資料庫連接配接數太多了，并且包含大量的活躍連接配接數請求。
從現象來看，是有些因素導緻資料庫連接配接數飙升，而造成應用無法連接配接的後果
接下來看下，資料庫以及主機各方面的具體性能名額，連接配接數是否真的出現飙升，與之相關的還有沒有其他的異常名額？
系統安裝了easydb，我們可以通過性能圖形，清晰地看到具體哪些性能名額出現了問題。
通過檢視該告警執行個體性能名額的曲線圖，發現從12月09日淩晨1點左右開始，出現連接配接數上漲的現象，上午09:16左右開始已經無法持續增長，直到09點50分左右基本完全釋放。這一點和剛才看到的error log中的報錯時間段基本吻合。
與主機的tcp連接配接趨勢圖基本吻合
那麼，接下來的任務就是要找到造成連接配接數飙升或者說大部分連接配接不釋放的原因。繼續對其他的性能名額的圖形進行了觀察。而其餘的資源消耗卻低得出人意料。
資料庫tps、qps與cpu使用率：
主機的cpu使用率以及io情況：
期間的qps、tps極低，并且cpu以及io資源完全處于空閑狀态，那麼期間的線程大部分應該是處于被阻塞的狀态。
而另外幾個關鍵的性能名額，在09點50分左右出現和連接配接數變化趨勢相反的極端，這點很出人意料。
除此之外，反常的性能曲線圖還包括主機的io吞吐量以及網絡吞吐量等資源：
先來分析下，09點50分之前的情況。這段時間的性能資料，簡單概述下，就是連接配接數上漲，而資源使用率極低。
這種情況的出現，一般來說有兩個導緻因素：一是鎖等待；第二是慢查詢。兩者的共性就是某些sql或者事務造成的連鎖阻塞，而最終全局或大範圍被阻塞。
然後看一下鎖等待的情況，
那麼，分析到這裡，問題基本可以定位為慢sql導緻的
接下來，目标似乎變得比較明朗了。就是找到出現阻塞現象的慢sql。
從09:00到10:00的慢日志報表中，發現了兩個執行時間超長的sql
直覺地看，12月08日晚上09點11分左右執行一個sql，這個sql執行大概消耗12h的時間！而12月09日01點02分執行的flush table操作，需要等待這個sql執行完成。而flush table被阻塞，就意味着，接下來的任何sql操作都會被阻塞。
單從這個現象來看，可以屢清前面發現的一些線索了：
1.淩晨一點開始的應用報錯，出現在flush table被阻塞之後，從這時候開始，可以建立連接配接，而sql無法執行。這也是後面被阻塞的線程都處于活躍狀态的原因
2.上午09點多出現的告警資訊，是因為此時資料庫已經無法再建立連接配接，agent程序無法連接配接mysql資料庫，持續5s後出現告警
3.09點16分到09點50分左右這段時間，mysql error log報錯與連接配接數曲線圖吻合，說明09點16分thread資源耗盡，而09點50分左右阻塞者執行完成，連接配接數釋放
4.兩類曲線圖變化反常關系解釋，慢sql從12月08日21點11分開始執行，經曆45453s的時間，恰好是上午09點50分左右，此時sql開始傳回資料，邏輯讀以及全表掃描名額急劇升高，同時還發現，這個sql可能是有排序操作的
那麼，這兩個時間點，都在做什麼？
與開發進行了簡單的溝通，并且排查了easydb的日志。前一天晚上09點11分是一個開發人員的報表查詢；而淩晨1點的flush操作，是全備任務的一個執行階段。
那麼似乎是這個開發人員跑了個很爛的sql導緻的？
接下來的排查，發現情況好像并沒這麼樂觀。
分析下這個sql，語句如下：
執行計劃如下：
從extras，我們看到，這個sql使用到了臨時表排序，并且貌似t_business_contacts表的關聯列沒有索引，all type下使用到了block nested loop算法
那麼，實際執行情況怎樣？
開發人員反映，昨晚的執行，隻用了2s不到的時間就擷取到了結果，而剛才的執行情況也确實如此。
由于系統自運作以來，整體負載一直比較低，查詢的資料量也不大，那麼即使這個sql語句有着不好的執行計劃，執行的時間應該也是比較樂觀的。但是從前面的現象來看，淩晨一點主庫上發起全備任務時，這個sql應該是還在執行。
再次檢視了21:16前後的系統負載，cpu以及io資源基本處于空閑，而qps也極低，而12月08日也沒有任何的慢sql記錄
如果隻是1s多的時間就傳回了資料，那麼這個慢sql從何而來？或許還有别的誤操作，導緻同樣的sql請求被發起，而這個相同的sql卡在某個執行的階段？從前面分析到的現象來看，這個sql直到第二天上午09點50才開始傳回資料。
仔細檢視各項名額，發現幾個系統名額在09号0點左右出現高峰，但是仍然無法解釋09點16分執行的sql被卡住
先保留這個疑問，這個sql無疑是有着較大的性能問題的，我們先對其做個優化處理。
按照如下操作，添加兩個索引:
<b>alter</b> <b>table</b> t_business_contacts <b>add</b> <b>index</b><b> </b><b> </b>idx_oi<b>(</b>org_id<b>),</b>algorithm<b>=</b>inplace<b>,</b><b>lock</b><b>=</b><b>none</b><b>;</b>
<b>alter</b> <b>table</b> t_system_organization <b>add</b> <b>index</b> idx_on<b>(</b>org_name<b>),</b>algorithm<b>=</b>inplace<b>,</b><b>lock</b><b>=</b><b>none</b><b>;</b>
從新的執行計劃，發現有了一些改觀，關聯字段通過索引等值比對，沒有了block nested loop算法，而in查詢取值池太大導緻優化器沒有選擇索引，優化器仍然使用了總行數隻有4000+的t_sup_qualifie_info表作為驅動表
接下來看下實際的執行效果：
執行效率有了接近40倍的提升！目前來看，優化效果還比較樂觀
前面還提到一個case，就是業務恢複的時間，基本是和告警時間相吻合。從前面的發現來看，現在的問題就是為什麼業務在資料庫執行個體連接配接數釋放之前就恢複了正常。
結合os message日志，很快就解除了疑惑。上午09點16分開始的日志内容如下：
從這裡可以看到，在目标執行個體不可用的時候，keepalived進行了主備的切換，是以，接下來的業務連接配接的都是原來的備執行個體。easydb上看到現在的複制關系拓撲圖如下：
目前為止，問題的産生過程、告警原因、業務恢複過程，都能夠有一個合理的解釋了。那麼現在的疑問就是，這個sql為什麼會這麼慢？
嘗試與開發人員進行溝通，看看這個sql當時執行的場景如何。
開發人員表示，當時是使用的用戶端工具進行的這個sql的查詢，人工查詢後将結果彙總到excel，而當時的查詢過程不到兩秒鐘的時間。那麼這個sql實質就是一個每天進行的一個報表查詢，這個流程已經進行了三個月，為何今天才出現問題？
結合sql執行期間的業務壓力以及系統的負載，基本很難構造出一個導緻這個sql執行如此耗時的場景。畢竟這個sql執行不是數百上千秒，而是12h，這與前面手工執行驗證的1.13s還是有着巨大差異的。
從資料庫的慢sql來看，有這樣一個sql執行慢，是肯定的，但是與開發人員的描述有極不相符，這個期間可能還是有些其他的異常情況，由于沒有曆史的show processlist資料，目前很難找到原因，看是否下次能夠在某些情況下重制類似的問題。
這是一個典型的連鎖阻塞，過程如下：
1.昨晚某個時間點，某個用戶端發起一個sql請求，很長時間沒有獲得響應
2.淩晨的自動備份執行到flush table階段，等待這個sql執行完成
3.之後的sql請求都被flush table阻塞
4.活躍連接配接數持續增加，導緻thread資源不可用，應用報錯
5.easydb agent無法擷取執行個體資訊，持續5分鐘觸發告警；keepalived檢測到主庫不可用，自動切庫
根因：
1.sql執行效率太低（原因未知）
2.主庫上有自動備份任務
對sql進行了優化之後，當天晚上關掉了所有主庫的自動備份任務，防止類似的情況導緻主庫不可用；
至于sql執行過程中到底發生了什麼，确實很值得探究，但可惜的是，mysql對曆史性能資料視圖支援的并不好，通過工具分析到的性能名額卻又和這個sql的執行情況完全相悖，或許如果能夠構造出一個這樣的場景，可能會有發現。