?劇本

因劇情所需，劇本顯示你在技術(shù)部門負(fù)責(zé)鏈路追蹤系統(tǒng)和數(shù)據(jù)庫中間件等，劇情為你日常工作中的一次排障經(jīng)歷...

剛看這么多，導(dǎo)演大喊：男主請就位... 預(yù)備 ! Action!

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

一、問題首現(xiàn)

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

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

同時，在你大腦的另一個區(qū)域也勾勒出如下數(shù)據(jù)流轉(zhuǎn)的畫面：

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

• 有嚴(yán)重的業(yè)務(wù)影響嘛？
• 最近系統(tǒng)有變更嘛？
• 這是個別記錄現(xiàn)象嘛？
• 以前發(fā)生過嘛？
• traceId 是什么？

得到的回復(fù)是：

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

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

1.1 canal 知識補充：

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

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

canal官網(wǎng)圖示.png

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

1.2 SkyWalking 知識補充：

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

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

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

二、詢問排查

2.1 梳理數(shù)據(jù)流轉(zhuǎn)

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

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

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

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

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

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

2.2 鎖定可疑環(huán)節(jié)

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

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

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

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

2.3 排查 Mybatis 緩存

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

2.3.1 排除一級緩存的嫌疑

一級緩存默認(rèn)是開啟的，是否一級緩存的問題呢？你繼續(xù)分析：

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

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

2.3.2 排除二級緩存的嫌疑

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

sqlSession 緩存的數(shù)據(jù)是先放在一級緩存中，當(dāng) sqlSession 會話提交或者關(guān)閉時會將一級緩存數(shù)據(jù)同步到二級緩存中

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

讀二級緩存.png

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

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

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

所有 mapper 都開啟

在 mybatis.xml 中加入以下配置

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

應(yīng)用 A 對照結(jié)論，沒有開啟 Mybatis 的二級緩存。

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

2.4 排查 binlog 同步

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

同步延遲.png

同時老王還補充，剛才已經(jīng)排查過 canal 和 MQ 的工作狀態(tài)，DBA 也看過 DB 的監(jiān)控信息，這幾個系統(tǒng)的指標(biāo)都很平穩(wěn)沒有抖動，如果有抖動的話，那出問題的應(yīng)該也不只是這一條記錄。

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

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

2.5 新的困境

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

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

三、接入 SkyWalking

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

只見編劇不慌不忙的走來后把劇本遞給導(dǎo)演，導(dǎo)演照著劇本認(rèn)真的讀了起來： "缺失有效的可觀測trace數(shù)據(jù)，又沒有辦法快速復(fù)現(xiàn)，可能只有上帝知道是哪個環(huán)節(jié)有問題，要不問問上帝？” 。

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

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

• 應(yīng)用配置中心勾選接入 SkyWalking
• 日志配置文件中調(diào)整加入 traceId 占位符?

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

四、終章劇透

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

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

本文轉(zhuǎn)載自微信公眾號「架構(gòu)染色」，可以通過以下二維碼關(guān)注。轉(zhuǎn)載本文請聯(lián)系聯(lián)系【架構(gòu)染色】公眾號作者。