這一週線上碰到一個詭異的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，你還想當然的代入去查詢問題，這當然會加大排查問題的難度。
