一個詭異的MySQL查詢超時問題，竟然隱藏着存在了兩年的BUG

這一週線上碰到一個詭異的BUG。

線上有個定時任務，這個任務須要查詢一個表幾天範圍內的一些數據作一些處理，每隔十分鐘執行一次，直至成功。

經過日誌發現，從凌晨5：26分開始到5：56任務執行了三次，三次都由於SQL查詢超時而執行失敗，而詭異的是，任務到凌晨6：00多就執行成功了。

天天都是凌晨五點多失敗，凌晨六點執行成功。

點開異常日誌一看是這樣的：

總結來講就是MySQL查詢超時。

像這種穩定復現的BUG，我原覺得只需三分鐘能定位，沒有想到卻耗費了我半天的時間。

排查之路

Explain

看到超時SQL，大多數人第一反應就是這個SQL沒有走索引，我也不例外，我當時的第一反應就是這條SQL沒有走索引。因而，我將日誌裏面的SQL複製了出來，脫敏處理一下大概是這樣的一條SQL：

select * from table_a where status_updated_at >= ? and status_updated_at < ?

SQL裏面有兩個日期參數，這兩個起始日期是某種商品的可交易時間區間，相隔三到五天，我取了17天的時間間隔的保守值，Explain了一下這條SQL。

從圖上能夠看到這條SQL的執行仍是走了索引的。走的是根據status_updated_at字段創建的索引。

執行了一下也只耗時了135毫秒。

根據Explain結果，我當時的推斷是：這條SQL確定走了索引，若是沒有走索引，那六點多鐘的查詢確定也會超時，由於這個表的數據是千萬級別的。

爲了驗證這一推斷，我找DBA幫我導出了一下凌晨5點到早上7點關於這個表的慢SQL，DBA告訴我那個時間段沒有關於這個表的慢SQL。

這也進一步驗證了我說推斷：這條SQL走了索引，只是在五點多的時候由於一些神祕緣由致使了超時。

接下來，須要作的就是找出這個神祕的緣由。

按照以往的經驗，我認爲有這幾點因素會致使查詢超時

• MySQL資源競爭
• 數據庫備份
• 網絡

MySQL資源競爭

首先，我經過監控系統查看了那段時間MySQL的運行狀況，鏈接數和CPU負載等指標都很是正常。因此，由於MySQL負載致使超時首先就能夠被排除。

那會不會是其餘業務操做這個表影響的呢？

首先，咱們線上數據庫事務隔離級別設置的是RR（可重複讀），由於MVCC的存在，簡單的修改確定是不會影響查詢至超時的。

要想影響惟一的可能性就是別的業務在update這個表數據的時候，更新條件沒有走索引，致使行鎖升級成表鎖，而且，這個操做要恰好在凌晨5點多執行，且持續了半個小時。

這個條件很是苛刻，我檢查了相關的代碼，問了相關負責人，並無這種狀況，全部的更新都是根據Id主鍵更新的。關鍵是，若是更新SQL的更新條件沒有走索引，確定會是一個慢SQL的，那麼，咱們在慢SQL日誌文件裏面就能找到它，實際上並無。

備份

是否是由於凌晨5點多，數據庫在備份的緣由呢？

首先備份鎖表不會鎖這麼久，這個任務是前先後後半個小時都執行失敗了；

其次咱們是備份的從庫，並非備份的主庫；

最後，咱們的備份任務都不是凌晨五點執行的。

因此，由於備份致使超時能夠排除了。

網絡

是否是網絡波動的緣由呢？

我找運維同窗幫忙看了一下執行任務的那臺機器那段時間的網絡狀況，很是平緩沒有絲毫問題，機房也沒有出現什麼網絡抖動的狀況。

再者，若是是網絡問題，確定會影響其餘任務和業務的，事實上，從監控系統中查看其餘業務並無什麼異常。

因此，由於網絡波動致使超時也能夠排除了。

起色

我前後排除了索引、網絡、備份、業務競爭MySQL資源等因素，在腦海裏模擬了N種狀況，腦補了一條SQL整個執行過程，想不到會有什麼其餘緣由了。

這個事情變得詭異了起來，DBA勸我暫時放棄，建議我把任務執行時間延後，加一些監控日誌再觀察觀察。畢竟，又不是不能用。

放棄是不可能放棄的，我是一個鐵頭娃，遇到BUG不解決睡不着覺。

理清思路，從頭來過，我向DBA要了一份線上五點到六點的慢SQL的文件，本身從新找了一遍，仍是沒有找到這個表相關的慢SQL。

在我忽然要放棄的時候，我忽然發現SQL日誌記錄裏面的時區都是標準時區的，而我那個任務執行的時候是北京時間，要知道標準時區和北京時區是差了8個小時的！

好傢伙！我都要想到量子力學了，結果發現時區沒對上？

會不會是DBA找慢SQL的時候時間找錯了啊？

我將這個「重大發現」告訴了DBA，DBA幫我從新跑一份慢SQL，好傢伙，出現了我想要那個表的慢SQL。

從日誌上面能夠看到，查詢的日期區間從2020年9月到2021年4月，時間跨度7個月。MySQL成本計算的時候認爲區間太大，走索引還不如直接掃描全表，最終沒有走索引掃描了1800W條數據。

說好的時間區間最多七天呢？怎麼變成了七個月？

趕忙定位代碼，定位發現底層在取時間區間時，調了一個RPC接口，這個接口預期返回的時間區間只有幾天，結果返回了七個月的時間區間。這段邏輯是18年上線的。

因而聯繫提供這個RPC接口的相關人員，經過查找驗證肯定這是底層數據的問題，應該返回幾天結果返回了幾個月。

最後修復了相關數據，增長了相應的校驗和監控，從新發布系統，這個存在了兩年的BUG也就得以解決了。

這個故事到這裏也就結束了。

再回顧一下，還有幾個問題須要回答一下：

不走索引，那爲何六點多執行就沒有超時呢？

緣由就是六點基本上沒有業務在調用MySQL，那個時候的MySQL的資源是很是充足的，加上MySQL的機器也配置很是的高，因此這條SQL硬生生跑成功了。聽起來有點離譜，但確實是這樣的。

爲何這個BUG在線上這麼久了，如今才發現？

這個時間區間底層數據用的很少，目前只發現只有這個超時SQL任務在調用。

原來業務量沒有這麼大，加上機器配置高，掃描整個表也花不了多久時間。凌晨五六點執行，沒有對線上的服務形成影響。

任務失敗是很正常的，由於還依賴一些其餘數據，其餘數據提供的時間不肯定，因此任務會一直跑直到成功。

總結

覆盤一下整個過程，對於這個查詢超時SQL問題的排查，我從索引、網絡、備份、業務競爭MySQL資源等方面一一分析，卻忽略了最重要的因素——執行的究竟是哪一條SQL。

我想固然的認爲執行的SQL就是我想象中的那樣並對此深信不疑，後面的努力也就成了徒勞。

這本是一個簡單的問題，我卻把他複雜化了，這是不該該的。

這是一個典型的例子，業務量不大的時候埋下的坑，業務發展迅速的時候就暴露了，萬幸的是，沒有影響到核心交易系統，若是是核心交易系統的話，可能就會致使一次P0的事故。

雖然這個代碼不是我寫的，但我從中獲得的教訓就是對線上環境要有敬畏之心，對依賴數據要有懷疑之心，對問題排查要有客觀之心。

線上的環境極其複雜，有着各自版本遷移和業務變動遺留下來的數據，這些狀況開發人員是沒法所有考慮到的，測試也很難覆蓋測試，帶着主觀的想法去寫代碼很容易致使BUG，有些BUG在業務量還不大的時候不容易引發重視，但隨着業務的發展，這些欠下的債終究要還。

你能夠保證你寫的邏輯沒有問題，可是你不能保證服務上游提供的數據都符合預期。多想一下若是上游數據異常，本身寫的服務會不會出問題，多加一些數據校驗和報警會省去不少沒必要要的麻煩。

排查問題的時候，必定要客觀，不要帶着主觀感覺。原本就是由於主觀而致使的BUG，你還想固然的代入去查找問題，這固然會加大排查問題的難度。