劇本殺 :《若不是SkyWalking,MySQL的這個鍋都沒人背了》-終章
本篇嘗試懸疑推理風劇本殺,劇情純屬虛構(若有雷同實屬巧合):應用 A 更新了 MySQL 數據 -> canal 監聽 binlog ,發給 MQ -> 應用 B 消費 MQ,并向 A 發起 Dubbo 請求 -> 應用 A 處理時卻查到了更新前的數據。這個情況多數人都沒遇到過,但提前了解并規避是必要的。
本劇本殺分上下兩章:
首章:《??若不是SkyWalking,MySQL的這個鍋都沒人背了-首章??》?
終章:《??若不是SkyWalking,MySQL的這個鍋都沒人背了-終章??》(本篇)
請按需回顧前情,方便你盡快融入角色(戲精上身)。
一、前情回顧
在首章劇情中你在技術部門負責鏈路追蹤系統和數據庫中間件等,在一次日常技術支持中,遇到了神奇的現象:
應用 A 將 MySQL 中 x 訂單記錄里的 y 字段從 ccc 變成了 ddd
canal 監聽 DB 中的訂單表,從 binlog 中感知到 x 記錄變更信息后,發到 MQ
應用 B 消費這個 MQ,收到這條消息后,處理流程中會再調用應用 A 的 Dubbo 服務,查詢一些信息
應用 A 響應 Dubbo 請求時,處理邏輯中還會從 MySQL 中查詢這條 x 訂單記錄,但是!!!讀出的狀態字段居然還是老數據 ccc
DB 是 MySQL ,采用讀寫分離架構,主從采用異步同步
你梳理的數據流轉圖如下:
數據流轉圖
通過這個數據流轉圖可以看出讀數據有如下 3 種途徑:
- 6.1 讀緩存
- 6.2 讀 slave-DB
- 6.3 讀 master-DB
你反復思索之后推測 6.1 或 6.2 這兩種途徑很可能會讀取到舊值,但經梳理排查將各方信息整合后,似乎并沒有執行 6.1 的讀緩存,也沒有執行 6.2 的讀 slave-DB,你也認定不會是數據庫中間件的路由機制有漏洞,而 DBA 也不認為 master-DB 有問題,應用 A 也不認為他指定讀 master-DB 的代碼有問題,老王也不認為他的 canal 讀到的 binlog 有問題。但由于沒有 trace 信息提供直接有效的證據,各方只能保留意見,不亂猜疑。
面面相覷好久,大家心照不宣地望向了導演,作為主角的你去問導演接下來怎么演。
導演也著急,把編劇叫來朝他怒吼:“那誰,這都演完了,你劇本還沒寫出來嘛?”
只見編劇不慌不忙的把劇本遞給導演,導演定睛一看,劇本上寫著"沒有有效的觀測數據,又沒有辦法復現,可能只有上帝視角知道是哪個環節有問題,要不問問上帝?”。
此時有人自稱上帝的站出來說:”應用 A、應用 B、canal 都接入 SkyWalking,等下次復現時,根據鏈路信息來尋找線索“。
二、終章劇本
因劇情所需,這次你在技術部門負責 canal 和 MQ 等,情節延續上一次的排障經歷...
突然,導演大喊:男主請就位... 預備 ! Action!
你:我去,咋的這就又開始演了?
三、心中的疑慮
當聽完上帝讓接 SkyWalking 后,你必須開始心中有疑慮,疑慮些什么呢?終章劇本要求作為主角的你,要好好想一想為什么接入 SkyWalking 后就能準確定位問題,幫助定位問題的信息 SkyWalking 是提供的?因為不擅長這個領域,你很頭疼;倘若剛好你很熟悉 SkyWalking ,這里也需要假裝不熟悉且頭疼一下,導演要求就這么演。。。
頭疼了一會兒,你突然想到隔壁老張,在首章中是主角,負責 SkyWalking ,于是你去咨詢 SkyWalking 能提供哪些有效的信息,老張拿出之前梳理的圖,指著其中幾個關鍵環節:
- 應用 A 什么時候開始更新記錄,什么時候結束更新記錄
- 應用 B 什么時候消費 MQ,什么時候請求應用 A,應用 A 什么時候開始執行的查詢,查詢的是哪里?用緩存沒?如果沒用緩存,訪問的又是哪個 DB?
這些關鍵信息 SkyWalking 的 trace 中都有記錄,且在界面中清晰可見,
老張繼續解釋說,雖然當前的 MySQL 沒有傳遞 traceId 信息,會導致鏈路斷開成更新和查詢這兩條 trace,但是可以通過關鍵字從日志中檢索出這兩條 trace 的 traceId(下文用 TID) 。
聽完老張的講解,你了解并相信了 SkyWalking 的能力。原本你也推測查詢的是 slave-DB 或緩存,所以當時下意識的決策就是等到復現后用 trace 信息來印證你的推測;不過老張在下班時又向你拋出一個疑慮:會不會真有當 canal 讀到 binlog 時 MySQL 事務還未完成提交的可能呢?
從你以往的經驗看是沒有這個情況的,但被老張這么一問卻不自信了。難道當前版本的 canal 同步 binlog 的機制有問題?“到底有沒有問題呢,到底有沒有呢?”這個聲音一直在你耳邊縈繞,莫名感讓你覺得很不踏實,于是之后便在空閑時搜集學習 MySQL 同步機制的更多內幕。
四、問題再現
大約兩周后,問題排查群突然出現@全員的消息,想到可能是問題再現,你趕緊點開查看;只見在群聊窗口中已經發出了把 x 記錄的 y 字段從 ccc 更新成 ddd 這個過程的 TID 以及 trace 信息截圖
非原截圖
因為劇情所需,作為本章主角的你,此時已很熟悉 SkyWalking 了,當看到這個截圖后,親自在 SkyWalking 的 web 頁中通過此 TID 查看 trace 信息,點擊Mysql/JDBI/Connection/commit,看到 commit 的具體信息如下:
Key | value | 描述解釋 |
服務 | serviceA | 應用 A 的服務名稱 |
服務實例 | 111.111.111.222 | 執行本次操作的實例 IP |
端點 | Mysql/JDBI/Connection/commit | commit操作的名稱信息 |
跨度類型 | Exit | Exit 表示訪問了外部資源,如此處的MySQL |
組件 | mysql-connector-java | 表明此 trace 信息是 JDBC 插件提供的 |
Peer | serviceA-xxxx:3311 | db 實例的域名\ip 信息 |
失敗 | false | false 表示本次操作沒有異常 |
db.type | sql | 表示本次操作的 DB 是 SQL 類型 |
db.instance | serviceA | 表示應用 A 的 DB 實例 |
db.statement | xxx | sql 語句 |
五、鐵證如山
你從 trace 信息中篩選出應用 A 將 x 訂單記錄里 y 字段從 ccc 變成了 ddd操作的關鍵信息是:
- 事務發生在 MySQL 實例 serviceA-xxxx 中(這是 master-DB)
- 事務 commit 的開始是 09:58:54 的 第 72 毫秒(后邊都只顯示毫秒)
- 事務 commit 的結束是在第 123 毫秒
之后又快速從 SkyWalking 的 web 頁中查看核實應用 A 查詢數據的 trace 信息,沒有讀 Mybatis 緩存、沒有讀 slave-DB,真兒真兒的是從 master-DB 中查詢數據。至此, trace 信息提供的信息有效證明了 應用 A 更新記錄和查詢記錄都發生在 master-DB serviceA-xxxx 中。
劇本提醒,擁有主角光環的你,此時已淡定、嫻熟的把兩條 trace 信息中關鍵事項的時間節點 結合 mysql 和 canal 日志(canal 系統還未接 SkyWalking,只能看日志信息)整理了出來,情況如下:
- 第 72 毫秒:應用 A 更新事務 commit 開始
- 第 73 毫秒:MySQL 服務端開始寫 Binlog
- 第 77 毫秒:canal 同步到 Binlog 后發送到 MQ
- 第 78 毫秒:應用 B 拉取到 canal 消息后,向應用 A 發起 Dubbo 調用
- 第 88 毫秒:應用 A 查詢 Mysql
- 第 123 毫秒:應用 A 的事務 commit 結束返回
劇本提醒:作為主角的你,絕對不能表現出驚訝,但其他群演看完你整理的信息后,必需配合表演出下圖中的表情(導演強調,怎么夸張怎么演)。
六、揭開玄機
因兩周前隔壁老張提出疑慮后,你就已經開始查閱資料學習 MySQL 8(今年是從 5.6 升級了)的同步機制,大腦知識庫中的資料顯示 MySQL 是分兩階段處理事物請求的,其中跟劇情密切相關的是第二階段的 3 個核心步驟:
- 寫 binlog
當寫完 biblog 后,事務已經提交并持久化了,若發生崩潰,重啟之后就能正確恢復
- 同步 binlog
各種同步機制有差異
- 寫 engine
會處理釋放鎖,釋放 mvcc 相關的 read view 等;注意只有寫完 engine 之后,事務中的變更才能被查詢到
- 客戶端 commit 請求返回
綜合上述的信息,你將整個流程整理成下圖:
讀寫流程時序
并在圖中指出,這兩次異常的情況的發生,全是因為在讀 x 記錄的時候,master-DB 中寫 engine 尚未完成,你之所以在上圖中使用2.謎之操作的名稱,是因為 MySQL 并不確定這個同步耗時是多長;而且在強同步、半同步的機制下實現邏輯更復雜,可能出現此問題的概率會比異步同步模式更高,因細節和劇情的關系不那么密切,本劇本里并沒有過多的描述,只提供了下邊這個更為細致的流程圖:
來自網絡
通過你給出的解釋和資料,除了老張的表情看起來是還在糾結著什么,其他眾人皆表示此瓜香甜可口、回味無窮,經過學習思考后對此情況基本達成共識,開始考慮如何應對這個小概率事件。
七、新的疑慮和答案
第二天下班后,老張又找到你探討為什么應用 A 的服務邏輯并未變更,而是升級 8.x 之后這個問題才開始出現(雖然概率不高);據老張講,昨夜他查閱了好多資料,其中有一個關鍵信息是寫 engine 后更新才能被查到,但是 5.7 開始,寫 engine 的時機被調整了:
5.6 版本中是先寫 engine 再同步,由于寫 engine 的時機較早,產生問題的概率就更低。
5.7 提供的默認邏輯是先同步,再寫 engine,由于同步前置了就可能帶來更多的具有不確定性的耗時
MySQL 5.7 默認同步機制的變化
八、建議
總結來看,無論是 5.6 還是 5.7 + ,從邏輯看只是概率不同,監聽 binlog 的方案始終是無法避免這類問題的。因無法確認 MySQL 的最大延遲時間,你的 canal 也無法使用 MQ 定時延遲消息的機制,因為延遲時間設大設小都不合適,你給出可行的 2 個建議:
異常重試 :異常時借助 MQ 的 delay 重試機制多試幾次。
采用新的實現架構:從根本上規避再去查詢 DB。
本文轉載自微信公眾號「架構染色」,可以通過以下二維碼關注。轉載本文請聯系聯系【架構染色】公眾號作者。