[[396942]]

圖片來(lái)自 Pexels

通過(guò)日志發(fā)現(xiàn)，從凌晨 5：26 分開(kāi)始到 5：56 任務(wù)執(zhí)行了三次，三次都因?yàn)?SQL 查詢超時(shí)而執(zhí)行失敗，而詭異的是，任務(wù)到凌晨 6：00 多就執(zhí)行成功了。

每天都是凌晨五點(diǎn)多失敗，凌晨六點(diǎn)執(zhí)行成功。

點(diǎn)開(kāi)異常日志一看是這樣的：

總結(jié)來(lái)說(shuō)就是 MySQL 查詢超時(shí)。像這種穩(wěn)定復(fù)現(xiàn)的 Bug，我原以為只需三分鐘能定位，沒(méi)有想到卻耗費(fèi)了我半天的時(shí)間。

01排查之路

①Explain

看到超時(shí) SQL，大多數(shù)人第一反應(yīng)就是這個(gè) SQL 沒(méi)有走索引，我也不例外，我當(dāng)時(shí)的第一反應(yīng)就是這條 SQL 沒(méi)有走索引。

于是，我將日志里面的 SQL 復(fù)制了出來(lái)，脫敏處理一下大概是這樣的一條 SQL：

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

SQL 里面有兩個(gè)日期參數(shù)，這兩個(gè)起始日期是某種商品的可交易時(shí)間區(qū)間，相隔三到五天，我取了 17 天的時(shí)間間隔的保守值，Explain 了一下這條 SQL。

從圖上可以看到這條 SQL 的執(zhí)行還是走了索引的。走的是根據(jù) status_updated_at 字段建立的索引。執(zhí)行了一下也只耗時(shí)了 135 毫秒。

根據(jù) Explain 結(jié)果，我當(dāng)時(shí)的推斷是：這條 SQL 肯定走了索引，如果沒(méi)有走索引，那六點(diǎn)多鐘的查詢肯定也會(huì)超時(shí)，因?yàn)檫@個(gè)表的數(shù)據(jù)是千萬(wàn)級(jí)別的。

為了驗(yàn)證這一推斷，我找 DBA 幫我導(dǎo)出了一下凌晨 5 點(diǎn)到早上 7 點(diǎn)關(guān)于這個(gè)表的慢 SQL，DBA 告訴我那個(gè)時(shí)間段沒(méi)有關(guān)于這個(gè)表的慢 SQL。

這也進(jìn)一步驗(yàn)證了我說(shuō)推斷：這條 SQL 走了索引，只是在五點(diǎn)多的時(shí)候因?yàn)橐恍┥衩卦驅(qū)е铝顺瑫r(shí)。

接下來(lái)，需要做的就是找出這個(gè)神秘的原因。按照以往的經(jīng)驗(yàn)，我認(rèn)為有這幾點(diǎn)因素會(huì)導(dǎo)致查詢超時(shí)：

• MySQL 資源競(jìng)爭(zhēng)
• 數(shù)據(jù)庫(kù)備份
• 網(wǎng)絡(luò)

②MySQL 資源競(jìng)爭(zhēng)

首先，我通過(guò)監(jiān)控系統(tǒng)查看了那段時(shí)間 MySQL 的運(yùn)行情況，連接數(shù)和 CPU 負(fù)載等指標(biāo)都非常正常。所以，因?yàn)?MySQL 負(fù)載導(dǎo)致超時(shí)首先就可以被排除。

那會(huì)不會(huì)是其他業(yè)務(wù)操作這個(gè)表影響的呢?首先，我們線上數(shù)據(jù)庫(kù)事務(wù)隔離級(jí)別設(shè)置的是 RR(可重復(fù)讀)，因?yàn)?MVCC 的存在，簡(jiǎn)單的修改肯定是不會(huì)影響查詢至超時(shí)的。

要想影響唯一的可能性就是別的業(yè)務(wù)在 update 這個(gè)表數(shù)據(jù)的時(shí)候，更新條件沒(méi)有走索引，導(dǎo)致行鎖升級(jí)成表鎖，并且，這個(gè)操作要?jiǎng)偤迷诹璩?5 點(diǎn)多執(zhí)行，且持續(xù)了半個(gè)小時(shí)。

這個(gè)條件非常苛刻，我檢查了相關(guān)的代碼，問(wèn)了相關(guān)負(fù)責(zé)人，并沒(méi)有這種情況，所有的更新都是根據(jù) Id 主鍵更新的。

關(guān)鍵是，如果更新 SQL 的更新條件沒(méi)有走索引，肯定會(huì)是一個(gè)慢 SQL 的，那么，我們?cè)诼?SQL 日志文件里面就能找到它，實(shí)際上并沒(méi)有。

③備份

是不是因?yàn)榱璩?5 點(diǎn)多，數(shù)據(jù)庫(kù)在備份的原因呢?

• 首先備份鎖表不會(huì)鎖這么久，這個(gè)任務(wù)是前前后后半個(gè)小時(shí)都執(zhí)行失敗了。
• 其次我們是備份的從庫(kù)，并不是備份的主庫(kù)。
• 最后，我們的備份任務(wù)都不是凌晨五點(diǎn)執(zhí)行的。

所以，因?yàn)閭浞輰?dǎo)致超時(shí)可以排除了。

④網(wǎng)絡(luò)

是不是網(wǎng)絡(luò)波動(dòng)的原因呢?我找運(yùn)維同學(xué)幫忙看了一下執(zhí)行任務(wù)的那臺(tái)機(jī)器那段時(shí)間的網(wǎng)絡(luò)情況，非常平緩沒(méi)有絲毫問(wèn)題，機(jī)房也沒(méi)有出現(xiàn)什么網(wǎng)絡(luò)抖動(dòng)的情況。

再者，如果是網(wǎng)絡(luò)問(wèn)題，肯定會(huì)影響其他任務(wù)和業(yè)務(wù)的，事實(shí)上，從監(jiān)控系統(tǒng)中查看其他業(yè)務(wù)并沒(méi)有什么異常。

所以，因?yàn)榫W(wǎng)絡(luò)波動(dòng)導(dǎo)致超時(shí)也可以排除了。

02轉(zhuǎn)機(jī)

我先后排除了索引、網(wǎng)絡(luò)、備份、業(yè)務(wù)競(jìng)爭(zhēng) MySQL 資源等因素，在腦海里模擬了 N 種情況，腦補(bǔ)了一條 SQL 整個(gè)執(zhí)行過(guò)程，想不到會(huì)有什么其他原因了。

這個(gè)事情變得詭異了起來(lái)，DBA 勸我暫時(shí)放棄，建議我把任務(wù)執(zhí)行時(shí)間延后，加一些監(jiān)控日志再觀察觀察。畢竟，又不是不能用。

放棄是不可能放棄的，我是一個(gè)鐵頭娃，遇到 Bug 不解決睡不著覺(jué)。

理清思路，從頭來(lái)過(guò)，我向 DBA 要了一份線上五點(diǎn)到六點(diǎn)的慢 SQL 的文件，自己重新找了一遍，還是沒(méi)有找到這個(gè)表相關(guān)的慢 SQL。

在我突然要放棄的時(shí)候，我突然發(fā)現(xiàn) SQL 日志記錄里面的時(shí)區(qū)都是標(biāo)準(zhǔn)時(shí)區(qū)的，而我那個(gè)任務(wù)執(zhí)行的時(shí)候是北京時(shí)間，要知道標(biāo)準(zhǔn)時(shí)區(qū)和北京時(shí)區(qū)是差了 8 個(gè)小時(shí)的!

好家伙!我都要想到量子力學(xué)了，結(jié)果發(fā)現(xiàn)時(shí)區(qū)沒(méi)對(duì)上?會(huì)不會(huì)是 DBA 找慢 SQL 的時(shí)候時(shí)間找錯(cuò)了啊?

我將這個(gè)“重大發(fā)現(xiàn)”告訴了 DBA，DBA 幫我重新跑一份慢 SQL，好家伙，出現(xiàn)了我想要那個(gè)表的慢 SQL。

從日志上面可以看到，查詢的日期區(qū)間從 2020 年 9 月到 2021 年 4 月，時(shí)間跨度 7 個(gè)月。

MySQL 成本計(jì)算的時(shí)候認(rèn)為區(qū)間太大，走索引還不如直接掃描全表，最終沒(méi)有走索引掃描了 1800W 條數(shù)據(jù)。

說(shuō)好的時(shí)間區(qū)間最多七天呢?怎么變成了七個(gè)月?

趕緊定位代碼，定位發(fā)現(xiàn)底層在取時(shí)間區(qū)間時(shí)，調(diào)了一個(gè) RPC 接口，這個(gè)接口預(yù)期返回的時(shí)間區(qū)間只有幾天，結(jié)果返回了七個(gè)月的時(shí)間區(qū)間。這段邏輯是 18 年上線的。

于是聯(lián)系提供這個(gè) RPC 接口的相關(guān)人員，通過(guò)查找驗(yàn)證確定這是底層數(shù)據(jù)的問(wèn)題，應(yīng)該返回幾天結(jié)果返回了幾個(gè)月。

最后修復(fù)了相關(guān)數(shù)據(jù)，增加了相應(yīng)的校驗(yàn)和監(jiān)控，重新發(fā)布系統(tǒng)，這個(gè)存在了兩年的 Bug 也就得以解決了。

這個(gè)故事到這里也就結(jié)束了。再回顧一下，還有幾個(gè)問(wèn)題需要回答一下：

①不走索引，那為什么六點(diǎn)多執(zhí)行就沒(méi)有超時(shí)呢?

原因就是六點(diǎn)基本上沒(méi)有業(yè)務(wù)在調(diào)用 MySQL，那個(gè)時(shí)候的 MySQL 的資源是非常充足的，加上 MySQL 的機(jī)器也配置非常的高，所以這條 SQL 硬生生跑成功了。聽(tīng)起來(lái)有點(diǎn)離譜，但確實(shí)是這樣的。

②為什么這個(gè) Bug 在線上這么久了，現(xiàn)在才發(fā)現(xiàn)?

這個(gè)時(shí)間區(qū)間底層數(shù)據(jù)用的不多，目前只發(fā)現(xiàn)只有這個(gè)超時(shí) SQL 任務(wù)在調(diào)用。

原來(lái)業(yè)務(wù)量沒(méi)有這么大，加上機(jī)器配置高，掃描整個(gè)表也花不了多久時(shí)間。凌晨五六點(diǎn)執(zhí)行，沒(méi)有對(duì)線上的服務(wù)造成影響。

任務(wù)失敗是很正常的，因?yàn)檫€依賴一些其他數(shù)據(jù)，其他數(shù)據(jù)提供的時(shí)間不確定，所以任務(wù)會(huì)一直跑直到成功。

03總結(jié)

復(fù)盤一下整個(gè)過(guò)程，對(duì)于這個(gè)查詢超時(shí) SQL 問(wèn)題的排查，我從索引、網(wǎng)絡(luò)、備份、業(yè)務(wù)競(jìng)爭(zhēng) MySQL 資源等方面一一分析，卻忽略了最重要的因素——執(zhí)行的到底是哪一條 SQL。

我想當(dāng)然的認(rèn)為執(zhí)行的 SQL 就是我想象中的那樣并對(duì)此深信不疑，后面的努力也就成了徒勞。

這本是一個(gè)簡(jiǎn)單的問(wèn)題，我卻把他復(fù)雜化了，這是不應(yīng)該的。

這是一個(gè)典型的例子，業(yè)務(wù)量不大的時(shí)候埋下的坑，業(yè)務(wù)發(fā)展迅速的時(shí)候就暴露了，萬(wàn)幸的是，沒(méi)有影響到核心交易系統(tǒng)，如果是核心交易系統(tǒng)的話，可能就會(huì)導(dǎo)致一次 P0 的事故。

雖然這個(gè)代碼不是我寫的，但我從中得到的教訓(xùn)就是「對(duì)線上環(huán)境要有敬畏之心，對(duì)依賴數(shù)據(jù)要有懷疑之心，對(duì)問(wèn)題排查要有客觀之心」。

線上的環(huán)境極其復(fù)雜，有著各自版本遷移和業(yè)務(wù)變更遺留下來(lái)的數(shù)據(jù)，這些情況開(kāi)發(fā)人員是無(wú)法全部考慮到的。

測(cè)試也很難覆蓋測(cè)試，帶著主觀的想法去寫代碼很容易導(dǎo)致 Bug，有些 Bug 在業(yè)務(wù)量還不大的時(shí)候不容易引起重視，但隨著業(yè)務(wù)的發(fā)展，這些欠下的債終究要還。

你可以保證你寫的邏輯沒(méi)有問(wèn)題，但是你不能保證服務(wù)上游提供的數(shù)據(jù)都符合預(yù)期。

多想一下如果上游數(shù)據(jù)異常，自己寫的服務(wù)會(huì)不會(huì)出問(wèn)題，多加一些數(shù)據(jù)校驗(yàn)和報(bào)警會(huì)省去很多不必要的麻煩。

排查問(wèn)題的時(shí)候，一定要客觀，不要帶著主觀感受相當(dāng)然的認(rèn)為是這樣。本來(lái)就是因?yàn)橹饔^操作而導(dǎo)致的 Bug，你還想當(dāng)然的代入去查找問(wèn)題，這當(dāng)然會(huì)加大排查問(wèn)題的難度。

作者：CoderW

編輯：陶家龍

出處：轉(zhuǎn)載自公眾號(hào)CoderW(ID：MHXJ_0810)