一個神奇SQL引發的故障【轉】

標籤：恢複   自動   全表掃描   保留   ora   loop   左右   grep   limit   

前幾天一個客戶資料庫主執行個體警示，診斷過程中發現是由一個慢SQL導致的資料庫故障，而在排查逐步深入之後卻發現這個現象的不可思議。

問題描述

2016年12日09日，大概9點26分左右，一個客戶的生產庫主執行個體發出警示，警示資訊如下：

MySQL執行個體超過五分鐘沒有更新。這個警示資訊簡單解釋下就是持續五分鐘無法擷取該執行個體的資訊。

同時開發人員還反映，從12月09日淩晨1點開始，已經出現一些資料庫請求逾時的現象，直到出現警示資訊之後業務恢複正常。

問題排查

1、監控進程排查

該資料庫系統使用袋鼠雲EasyDB進行效能監控以及警示，easydb服務端無法擷取agent方的資訊，那麼首要任務，就是檢查easydb agent是否存活。

從可見，easydb進程工作正常。那麼接下來就要從資料庫以及伺服器層面去排查

2、MySQL error log

先看下MySQL error日誌有沒有報錯資訊的記錄。登陸主機，首先瞭解MySQL的安裝情況：

[[email protected] ~]# 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分

簡單分析一下報錯資訊的含義：

[[email protected] bin]# ./perror 11

OS error code 11: Resource temporarily unavailable

報錯的資訊大致意思是，資源暫時不可用，那麼這個資源指的是什嗎？就是thread。從這裡可以看出，資料庫連接數太多了，並且包含大量的活躍串連數請求。

從現象來看，是有些因素導致資料庫連接數飆升，而造成應用無法串連的後果

3、效能指標

接下來看下，資料庫以及主機各方面的具體效能指標，串連數是否真的出現飆升，與之相關的還有沒有其他的異常指標？

系統安裝了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導致的

4、MySQL 慢日誌

接下來，目標似乎變得比較明朗了。就是找到出現阻塞現象的慢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表的關聯列沒有索引，而使用到了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無疑是有著較大的效能問題的，我們先對其做個最佳化處理。

按照如下操作，添加兩個索引:

altertable t_business_contacts addindexidx_oi(org_id),ALGORITHM=INPLACE,LOCK=NONE;

altertable t_system_organization addindexidx_on(ORG_NAME),ALGORITHM=INPLACE,LOCK=NONE;

從新的執行計畫，發現有了一些改觀，沒有了Nested Loop演算法，而in查詢取值池太大導致最佳化器沒有選擇索引，最佳化器仍然使用了總行數只有4000+的t_sup_qualifie_info表作為驅動表

接下來看下實際的執行效果：

執行效率有了接近40倍的提升！目前來看，最佳化效果還比較樂觀

5、message日誌

前面還提到一個CASE，就是業務恢複的時間，基本是和警示時間相吻合。從前面的發現來看，現在的問題就是為什麼業務在資料庫執行個體串連數釋放之前就恢複了正常。

結合OS message日誌，很快就解除了疑惑。上午09點16分開始的日誌內容如下：

從這裡可以看到，在目標執行個體停用時候，keepalived進行了主備的切換，因此，接下來的Business Connectivity的都是原來的備執行個體。Easydb上看到現在的複製關係拓撲圖如下：

6、SQL執行情境溝通

目前為止，問題的產生過程、警示原因、業務恢複過程，都能夠有一個合理的解釋了。那麼現在的疑問就是，這個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的執行情況完全相悖，或許如果能夠構造出一個這樣的情境，可能會有發現。

一個神奇SQL引發的故障【轉】