?劇本

因劇情所需，劇本顯示你在技術部門負責鏈路追蹤系統和數據庫中間件等，劇情為你日常工作中的一次排障經歷...

剛看這么多，導演大喊：男主請就位... 預備 ! Action!

你：哇喔，我這就開始演了？

一、問題首現

記得那是一個風和日麗的下午...突然你被拉到一個臨時工作群里，只見窗口中快速彈出一條消息：@老張 binlog 中的字段更新，讀 db 時卻讀不到。記住作為男主的你在劇本的這個章節里叫老張，看到這個消息后，你的大腦便開始拆解這些關鍵字：

• 應用 A 將 MySQL 中 x 記錄中的 y 字段更新了
• canal（canal 是啥，下邊有介紹）監聽 DB 中訂單記錄變更事件，發到 MQ
• 應用 B 消費這個 MQ, 收到這個消息后，從 MySQL 中查詢這個 x 記錄
• 但是！??！沒讀到 y 字段更新后的值

同時，在你大腦的另一個區域也勾勒出如下數據流轉的畫面：

對此問題有了初步畫像后，你的大腦中條件反應式的冒出了一連串問題，趕緊在群里發出：

• 有嚴重的業務影響嘛？
• 最近系統有變更嘛？
• 這是個別記錄現象嘛？
• 以前發生過嘛？
• traceId 是什么？

得到的回復是：

• 問題不嚴重。
• 最近沒變更。
• 這是個別記錄現象。
• 以前好像沒遇到過。
• 還沒有接入 SkyWalking（SkyWalking 是啥，下邊會介紹），現有的日志里也都看不出什么貓膩。

看完前 4 個回答后得知沒有嚴重影響，你松了一口氣，緊張的情緒緩和了下來；但同時也意識到沒有直觀的鏈路追蹤數據，要理清楚這個問題就有點麻煩了。

1.1 canal 知識補充：

官方這么介紹：canal [k?'n?l] ，譯意為水道/管道/溝渠，主要用途是基于 MySQL 數據庫增量日志解析，提供增量數據訂閱和消費。

早期阿里巴巴因為杭州和美國雙機房部署，存在跨機房同步的業務需求，實現方式主要是基于業務 trigger 獲取增量變更。從 2010 年開始，業務逐步嘗試數據庫日志解析獲取增量變更進行同步，由此衍生出了大量的數據庫增量訂閱和消費業務。

canal官網圖示.png

github 地址：https://github.com/alibaba/canal

1.2 SkyWalking 知識補充：

SkyWalking 是一個可觀測性平臺（Observability Analysis Platform 簡稱 OAP）和應用性能管理系統（Application Performance Management 簡稱 APM）。提供分布式鏈路追蹤、服務網格（Service Mesh）遙測分析、度量（Metric）聚合和可視化一體化解決方案。

下圖即其鏈路追蹤的展示效果，通過它能夠直觀看出一次請求完整的執行軌跡，經過了哪些應用、訪問了哪些中間件、請求的關鍵信息是什么、各環節的執行耗時是多少、是否異常等。

github 地址：https://skywalking.apache.org/

二、詢問排查

2.1 梳理數據流轉

因為應用沒有接入 SkyWalking，缺少直觀完整 trace 信息的幫助，你只能通過低效的、人工詢問的方式梳理有哪些應用、DB 什么類型、數據流轉情況，經過一番溝通后才了解到情況如下：

應用 A 將 MySQL 中 x 訂單記錄中 y 字段從 ccc 變成了 ddd

canal 監聽 DB 中訂單表，從 binlog 中感知到 x 記錄變更信息后，發到 MQ

應用 B 消費這個 MQ，收到這條消息后，處理流程中會再請求應用 A 的 Dubbo 接口，查詢一些信息

應用 A 收到 Dubbo 請求后，處理邏輯中還會從 MySQL 中查詢這個 x 訂單記錄，但是?。。∽x出的狀態字段居然還是 ccc

DB 是讀寫分離，MySQL 主從同步采用的異步同步模式

2.2 鎖定可疑環節

基于前邊掌握的情況，你在大腦中快速勾勒出如下這個數據流傳圖：

通過這個數據流傳圖可以看出讀數據有如下 3 種途徑：

• 6.1 讀緩存
• 6.2 讀從庫
• 6.3 讀主庫

你反復思索之后推測 6.1 或 6.2 這兩種途徑很可能會讀取到舊值，于是開始排查。

2.3 排查 Mybatis 緩存

你依據經驗推測， 6.1 最有可能讀不到新數據，緩存通常有進程內緩存、Redis 緩存，Mybatis 緩存這幾種。進一步溝通后，你確認了應用 A 并沒有使用內存緩存和 Redis 緩存，同事甚至有懷疑數據庫中間件中是否有緩存，這個懷疑被你直接排除了（數據庫中間件中沒有緩存），那就剩下 Mybatis 緩存這一處嫌疑了，于是你快速從大腦的知識庫中翻出 Mybatis 兩級緩存的機制原理。

2.3.1 排除一級緩存的嫌疑

一級緩存默認是開啟的，是否一級緩存的問題呢？你繼續分析：

• 按照現有 mapper 的用法，一個請求中所有的 CRUD 操作都是在同一個 sqlSession 里面
• 一個 sqlSession 內的所有查詢操作都會保存到這個 sqlSession 內緩存中，即每個請求都有一個專屬于自己的一級緩存
• 每個請求的一級緩存隔離，彼此互不干擾
• 應用 A 在 x 記錄更新前，查詢請求中的一級緩存數據，不會被應用 A 在 x 記錄更新后的查詢請求訪問到。

如此梳理分析后，你排除了 Mybatis 一級緩存造成此問題的可能。

2.3.2 排除二級緩存的嫌疑

然后你繼續開始排查是否由二級緩存導致的，你的知識庫顯示：二級緩存在 sqlSession 之外，被 sqlSession 共享，即多個請求可以共用同一個二級緩存，一、二級緩存的協作機制如下：

sqlSession 緩存的數據是先放在一級緩存中，當 sqlSession 會話提交或者關閉時會將一級緩存數據同步到二級緩存中

用戶查詢時，會先去二級緩存中查找，若找不到才去一級緩存中查找

讀二級緩存.png

這么看來如果時差吻合，二級緩存的嫌疑很大，那是不是二級緩存的問題呢？此時一個知識點在使勁的敲擊你的大腦【二級緩存需要手動開啟】 ，于是你抓緊咨詢應用 A 是否開啟了二級緩存，但同事一時間又搞不清楚這個開關的知識，于是你把開啟二級緩存的方式描述發出：

單個 mapper 開啟在需要開啟二級緩存的 XXXmapper.xml 文件中加入以下配置

<!-- 開啟單個mapper的二級緩存-->
<cache />

所有 mapper 都開啟

在 mybatis.xml 中加入以下配置

<settings>
    <!--  開啟所有mapper的二級緩存 -->
    <!--<setting name="cacheEnabled" value="true" />-->
</settings>

應用 A 對照結論，沒有開啟 Mybatis 的二級緩存。

如此梳理分析后，你又排除了 Mybatis 二級緩存造成此問題的可能。

2.4 排查 binlog 同步

依據上圖你繼續排查，此時懷疑到了 6.2 讀從庫這個環節，跟 DBA 核實得知，這個 MySQL 主從同步采用了異步同步方案；此刻你的知識庫表示很尷尬：MySQL 異步同步機制并不熟悉，于是找到隔壁老王（canal、MQ 專家）請教，老王解釋到：異步同步的機制中，master-DB 寫 binlog 后執行提交，不等待 slave-DB 的同步狀態；既然 canal 和 slave-DB 都是讀取 binlog 數據之后再做處理，且無順序管控，那就有可能當應用 A 從 slave-DB 讀 x 記錄時，slave-DB 還未完成 x 記錄的同步，情況如下圖：

同步延遲.png

同時老王還補充，剛才已經排查過 canal 和 MQ 的工作狀態，DBA 也看過 DB 的監控信息，這幾個系統的指標都很平穩沒有抖動，如果有抖動的話，那出問題的應該也不只是這一條記錄。

當掌握了這些信息后，你基本認定應用 A 是讀了 slave-DB，因為你的數據庫中間件，在讀寫分離的場景中，默認情況下讀請求是自動路由到 slave-DB 的，除非...，突然你跟應用 A 核實，這個讀請求有沒有指定強制讀master-DB...，應用 A 的回復跟你的預期相差很大，這個請求中他指定了讀master-DB。

為什么為什么讀 master-DB，還能讀到的是老數據，難道是數據庫中間件的路由機制有漏洞了？導演讓你馬上配合表演出了上圖中的表情...OH MY GOD ?。?！

2.5 新的困境

過了好一會兒，你冷靜了下來，憑借你的堅強的靈魂，你認定不是數據庫中間件的路由機制有漏洞，而此時 DBA 也不認為 master-DB 有問題，應用 A 也不認為他指定讀 master-DB 的代碼有問題，老王也不認為他的 canal 讀到的 binlog 有問題。

面面相覷好久，大家心照不宣的望向了導演，而你作為主角，自然由你去問導演接下來要怎么演。

三、接入 SkyWalking

導演著急的大吼：“那誰，這都演完了，你劇本還沒寫出來嘛？”

只見編劇不慌不忙的走來后把劇本遞給導演，導演照著劇本認真的讀了起來： "缺失有效的可觀測trace數據，又沒有辦法快速復現，可能只有上帝知道是哪個環節有問題，要不問問上帝？” 。

此時突然有人站起來說：”我演的是上帝，應用 A、應用 B 接下來接一下 SkyWalking 吧，等下次復現時，大家就能根據鏈路信息來快速揭秘問題真相“。

于是你在群里發出接入 SkyWalking 的文檔，兩個點很簡單：

• 應用配置中心勾選接入 SkyWalking
• 日志配置文件中調整加入 traceId 占位符?

梳理分析至此，眾人沒了方向，也都保留了各自的懷疑，期待接入 SkyWalking 后再遇到，依據精確的信息來定位。

四、終章劇透

在下一章（終章）的劇本中，你是主角老王；上邊這種尷尬的狀況把你那股較真兒的勁頭給激活了，之后你查閱了許多資料，進一步學習了 MySQL 的同步機制，在問題復現后，給出了 MySQL 同步機制有缺陷的根因...。敬請期待終章，關鍵劇情如下：

• 應用 A、應用 B 之后接入了 SkyWalking
• 兩周后，這個問題又出現了
• SkyWalking 中 trace 信息表明應用 A 的確是讀了 master-DB
• 老王通過進一步搜集研究發現，這是 MySQL 工作機制中天然存在的缺陷
• 眾人商定了后續的改進和規范調整，以應對這個缺陷

本文轉載自微信公眾號「架構染色」，可以通過以下二維碼關注。轉載本文請聯系聯系【架構染色】公眾號作者。