一個詭異的MySQL查詢超時，居然揭開了隱藏了兩年的BUG
這一周線上碰到一個詭異的BUG。
線上有個定時任務(wù)慷吊，這個任務(wù)需要查詢一個表幾天范圍內(nèi)的一些數(shù)據(jù)做一些處理，每隔十分鐘執(zhí)行一次躺率，直至成功。
通過日志發(fā)現(xiàn)讼积，從凌晨5：26分開始到5：56任務(wù)執(zhí)行了三次肥照，三次都因為SQL查詢超時而執(zhí)行失敗，而詭異的是勤众，任務(wù)到凌晨6：00多就執(zhí)行成功了。
每天都是凌晨五點多失敗鲤脏，凌晨六點執(zhí)行成功们颜。
<img src="https://coder-wang-1304346453.cos.ap-beijing.myqcloud.com/blog/20210418175649.png" alt="image-20210418175649354" />
點開異常日志一看是這樣的：
<img src="https://coder-wang-1304346453.cos.ap-beijing.myqcloud.com/blog/20210417150156.png" alt="image-20210417150156357" />
總結(jié)來說就是MySQL查詢超時吕朵。
像這種穩(wěn)定復現(xiàn)的BUG，我原以為只需三分鐘能定位窥突，沒有想到卻耗費了我半天的時間努溃。
排查之路
Explain
看到超時SQL，大多數(shù)人第一反應(yīng)就是這個SQL沒有走索引阻问，我也不例外梧税，我當時的第一反應(yīng)就是這條SQL沒有走索引。于是称近，我將日志里面的SQL復制了出來第队，脫敏處理一下大概是這樣的一條SQL：
select * from table_a where status_updated_at >= ? and status_updated_at < ?
SQL里面有兩個日期參數(shù)，這兩個起始日期是某種商品的可交易時間區(qū)間刨秆，相隔三到五天凳谦，我取了17天的時間間隔的保守值，Explain了一下這條SQL衡未。
<img src="https://coder-wang-1304346453.cos.ap-beijing.myqcloud.com/blog/20210417183530.png" alt="image-20210417183529957" />
從圖上可以看到這條SQL的執(zhí)行還是走了索引的尸执。走的是根據(jù)status_updated_at字段建立的索引。
執(zhí)行了一下也只耗時了135毫秒缓醋。
<img src="https://coder-wang-1304346453.cos.ap-beijing.myqcloud.com/blog/20210417183426.png" alt="image-20210417183426651" />
根據(jù)Explain結(jié)果如失，我當時的推斷是：這條SQL肯定走了索引，如果沒有走索引送粱，那六點多鐘的查詢肯定也會超時岖常，因為這個表的數(shù)據(jù)是千萬級別的。
為了驗證這一推斷葫督，我找DBA幫我導出了一下凌晨5點到早上7點關(guān)于這個表的慢SQL竭鞍，DBA告訴我那個時間段沒有關(guān)于這個表的慢SQL。
這也進一步驗證了我說推斷：這條SQL走了索引橄镜，只是在五點多的時候因為一些神秘原因?qū)е铝顺瑫r偎快。
接下來，需要做的就是找出這個神秘的原因洽胶。
按照以往的經(jīng)驗晒夹，我認為有這幾點因素會導致查詢超時
- MySQL資源競爭
- 數(shù)據(jù)庫備份
- 網(wǎng)絡(luò)
MySQL資源競爭
首先，我通過監(jiān)控系統(tǒng)查看了那段時間MySQL的運行情況姊氓，連接數(shù)和CPU負載等指標都非常正常丐怯。所以，因為MySQL負載導致超時首先就可以被排除翔横。
那會不會是其他業(yè)務(wù)操作這個表影響的呢读跷？
首先，我們線上數(shù)據(jù)庫事務(wù)隔離級別設(shè)置的是RR（可重復讀）禾唁，因為MVCC的存在效览，簡單的修改肯定是不會影響查詢至超時的无切。
要想影響唯一的可能性就是別的業(yè)務(wù)在update這個表數(shù)據(jù)的時候，更新條件沒有走索引丐枉，導致行鎖升級成表鎖哆键，并且，這個操作要剛好在凌晨5點多執(zhí)行瘦锹，且持續(xù)了半個小時籍嘹。
這個條件非常苛刻弯院，我檢查了相關(guān)的代碼辱士，問了相關(guān)負責人，并沒有這種情況抽兆，所有的更新都是根據(jù)Id主鍵更新的识补。關(guān)鍵是，如果更新SQL的更新條件沒有走索引辫红，肯定會是一個慢SQL的凭涂，那么，我們在慢SQL日志文件里面就能找到它贴妻，實際上并沒有切油。
備份
是不是因為凌晨5點多，數(shù)據(jù)庫在備份的原因呢名惩？
首先備份鎖表不會鎖這么久澎胡，這個任務(wù)是前前后后半個小時都執(zhí)行失敗了；
其次我們是備份的從庫娩鹉，并不是備份的主庫攻谁；
最后，我們的備份任務(wù)都不是凌晨五點執(zhí)行的弯予。
所以戚宦，因為備份導致超時可以排除了。
網(wǎng)絡(luò)
是不是網(wǎng)絡(luò)波動的原因呢锈嫩？
我找運維同學幫忙看了一下執(zhí)行任務(wù)的那臺機器那段時間的網(wǎng)絡(luò)情況受楼，非常平緩沒有絲毫問題，機房也沒有出現(xiàn)什么網(wǎng)絡(luò)抖動的情況呼寸。
再者艳汽，如果是網(wǎng)絡(luò)問題，肯定會影響其他任務(wù)和業(yè)務(wù)的对雪，事實上河狐，從監(jiān)控系統(tǒng)中查看其他業(yè)務(wù)并沒有什么異常。
所以，因為網(wǎng)絡(luò)波動導致超時也可以排除了甚牲。
轉(zhuǎn)機
我先后排除了索引义郑、網(wǎng)絡(luò)蝶柿、備份丈钙、業(yè)務(wù)競爭MySQL資源等因素，在腦海里模擬了N種情況交汤，腦補了一條SQL整個執(zhí)行過程雏赦，想不到會有什么其他原因了。
這個事情變得詭異了起來芙扎，DBA勸我暫時放棄星岗，建議我把任務(wù)執(zhí)行時間延后，加一些監(jiān)控日志再觀察觀察戒洼。畢竟俏橘，又不是不能用。
放棄是不可能放棄的圈浇，我是一個鐵頭娃寥掐，遇到BUG不解決睡不著覺。
理清思路磷蜀，從頭來過召耘，我向DBA要了一份線上五點到六點的慢SQL的文件，自己重新找了一遍褐隆，還是沒有找到這個表相關(guān)的慢SQL污它。
在我突然要放棄的時候，我突然發(fā)現(xiàn)SQL日志記錄里面的時區(qū)都是標準時區(qū)的庶弃，而我那個任務(wù)執(zhí)行的時候是北京時間衫贬，要知道標準時區(qū)和北京時區(qū)是差了8個小時的！
<img src="https://coder-wang-1304346453.cos.ap-beijing.myqcloud.com/blog/20210418171840.png" alt="image-20210418171840432" />
好家伙歇攻！我都要想到量子力學了固惯，結(jié)果發(fā)現(xiàn)時區(qū)沒對上？
會不會是DBA找慢SQL的時候時間找錯了暗舴缝呕？
我將這個“重大發(fā)現(xiàn)”告訴了DBA，DBA幫我重新跑一份慢SQL斧散，好家伙供常，出現(xiàn)了我想要那個表的慢SQL。
<img src="https://coder-wang-1304346453.cos.ap-beijing.myqcloud.com/blog/20210418155059.png" alt="image-20210418155058957" />
從日志上面可以看到鸡捐，查詢的日期區(qū)間從2020年9月到2021年4月栈暇，時間跨度7個月。MySQL成本計算的時候認為區(qū)間太大箍镜，走索引還不如直接掃描全表源祈，最終沒有走索引掃描了1800W條數(shù)據(jù)煎源。
說好的時間區(qū)間最多七天呢？怎么變成了七個月香缺？
趕緊定位代碼手销，定位發(fā)現(xiàn)底層在取時間區(qū)間時，調(diào)了一個RPC接口图张，這個接口預(yù)期返回的時間區(qū)間只有幾天锋拖，結(jié)果返回了七個月的時間區(qū)間。這段邏輯是18年上線的祸轮。
于是聯(lián)系提供這個RPC接口的相關(guān)人員兽埃，通過查找驗證確定這是底層數(shù)據(jù)的問題，應(yīng)該返回幾天結(jié)果返回了幾個月适袜。
最后修復了相關(guān)數(shù)據(jù)柄错，增加了相應(yīng)的校驗和監(jiān)控，重新發(fā)布系統(tǒng)苦酱，這個存在了兩年的BUG也就得以解決了售貌。
這個故事到這里也就結(jié)束了。
再回顧一下躏啰，還有幾個問題需要回答一下：
不走索引趁矾，那為什么六點多執(zhí)行就沒有超時呢？
原因就是六點基本上沒有業(yè)務(wù)在調(diào)用MySQL给僵，那個時候的MySQL的資源是非常充足的毫捣，加上MySQL的機器也配置非常的高，所以這條SQL硬生生跑成功了帝际。聽起來有點離譜蔓同，但確實是這樣的。
為什么這個BUG在線上這么久了蹲诀，現(xiàn)在才發(fā)現(xiàn)斑粱？
這個時間區(qū)間底層數(shù)據(jù)用的不多，目前只發(fā)現(xiàn)只有這個超時SQL任務(wù)在調(diào)用脯爪。
原來業(yè)務(wù)量沒有這么大则北，加上機器配置高，掃描整個表也花不了多久時間痕慢。凌晨五六點執(zhí)行尚揣，沒有對線上的服務(wù)造成影響。
任務(wù)失敗是很正常的掖举，因為還依賴一些其他數(shù)據(jù)快骗，其他數(shù)據(jù)提供的時間不確定，所以任務(wù)會一直跑直到成功。
總結(jié)
復盤一下整個過程方篮，對于這個查詢超時SQL問題的排查名秀，我從索引、網(wǎng)絡(luò)藕溅、備份匕得、業(yè)務(wù)競爭MySQL資源等方面一一分析，卻忽略了最重要的因素——執(zhí)行的到底是哪一條SQL蜈垮。
我想當然的認為執(zhí)行的SQL就是我想象中的那樣并對此深信不疑耗跛，后面的努力也就成了徒勞裕照。
這本是一個簡單的問題攒发，我卻把他復雜化了，這是不應(yīng)該的晋南。
這是一個典型的例子惠猿，業(yè)務(wù)量不大的時候埋下的坑，業(yè)務(wù)發(fā)展迅速的時候就暴露了负间，萬幸的是偶妖，沒有影響到核心交易系統(tǒng)，如果是核心交易系統(tǒng)的話政溃，可能就會導致一次P0的事故趾访。
雖然這個代碼不是我寫的，但我從中得到的教訓就是對線上環(huán)境要有敬畏之心董虱，對依賴數(shù)據(jù)要有懷疑之心扼鞋，對問題排查要有客觀之心。
線上的環(huán)境極其復雜愤诱，有著各自版本遷移和業(yè)務(wù)變更遺留下來的數(shù)據(jù)云头，這些情況開發(fā)人員是無法全部考慮到的，測試也很難覆蓋測試淫半，帶著主觀的想法去寫代碼很容易導致BUG溃槐，有些BUG在業(yè)務(wù)量還不大的時候不容易引起重視，但隨著業(yè)務(wù)的發(fā)展科吭，這些欠下的債終究要還昏滴。
你可以保證你寫的邏輯沒有問題，但是你不能保證服務(wù)上游提供的數(shù)據(jù)都符合預(yù)期对人。多想一下如果上游數(shù)據(jù)異常谣殊，自己寫的服務(wù)會不會出問題，多加一些數(shù)據(jù)校驗和報警會省去很多不必要的麻煩规伐。
排查問題的時候蟹倾，一定要客觀，不要帶著主觀感受。本來就是因為主觀而導致的BUG鲜棠，你還想當然的代入去查找問題肌厨，這當然會加大排查問題的難度。
