[[396942]]

圖片來自 Pexels

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

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

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

總結來說就是 MySQL 查詢超時。像這種穩定復現的 Bug，我原以為只需三分鐘能定位，沒有想到卻耗費了我半天的時間。

01排查之路

①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 點多，數據庫在備份的原因呢?

• 首先備份鎖表不會鎖這么久，這個任務是前前后后半個小時都執行失敗了。
• 其次我們是備份的從庫，并不是備份的主庫。
• 最后，我們的備份任務都不是凌晨五點執行的。

所以，因為備份導致超時可以排除了。

④網絡

是不是網絡波動的原因呢?我找運維同學幫忙看了一下執行任務的那臺機器那段時間的網絡情況，非常平緩沒有絲毫問題，機房也沒有出現什么網絡抖動的情況。

再者，如果是網絡問題，肯定會影響其他任務和業務的，事實上，從監控系統中查看其他業務并沒有什么異常。

所以，因為網絡波動導致超時也可以排除了。

02轉機

我先后排除了索引、網絡、備份、業務競爭 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 任務在調用。

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

任務失敗是很正常的，因為還依賴一些其他數據，其他數據提供的時間不確定，所以任務會一直跑直到成功。

03總結

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

我想當然的認為執行的 SQL 就是我想象中的那樣并對此深信不疑，后面的努力也就成了徒勞。

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

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

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

線上的環境極其復雜，有著各自版本遷移和業務變更遺留下來的數據，這些情況開發人員是無法全部考慮到的。

測試也很難覆蓋測試，帶著主觀的想法去寫代碼很容易導致 Bug，有些 Bug 在業務量還不大的時候不容易引起重視，但隨著業務的發展，這些欠下的債終究要還。

你可以保證你寫的邏輯沒有問題，但是你不能保證服務上游提供的數據都符合預期。

多想一下如果上游數據異常，自己寫的服務會不會出問題，多加一些數據校驗和報警會省去很多不必要的麻煩。

排查問題的時候，一定要客觀，不要帶著主觀感受相當然的認為是這樣。本來就是因為主觀操作而導致的 Bug，你還想當然的代入去查找問題，這當然會加大排查問題的難度。

作者：CoderW

編輯：陶家龍

出處：轉載自公眾號CoderW(ID：MHXJ_0810)