?劇本

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

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

你：哇喔，我這就開(kāi)始演了？

一、問(wèn)題首現(xiàn)

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

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

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

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

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

得到的回復(fù)是：

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

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

1.1 canal 知識(shí)補(bǔ)充：

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

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

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

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

1.2 SkyWalking 知識(shí)補(bǔ)充：

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

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

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

二、詢問(wèn)排查

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

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

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

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

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

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

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

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

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

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

• 6.1 讀緩存
• 6.2 讀從庫(kù)
• 6.3 讀主庫(kù)

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

2.3 排查 Mybatis 緩存

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

2.3.1 排除一級(jí)緩存的嫌疑

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

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

如此梳理分析后，你排除了 Mybatis 一級(jí)緩存造成此問(wèn)題的可能。

2.3.2 排除二級(jí)緩存的嫌疑

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

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

用戶查詢時(shí)，會(huì)先去二級(jí)緩存中查找，若找不到才去一級(jí)緩存中查找

讀二級(jí)緩存.png

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

單個(gè) mapper 開(kāi)啟在需要開(kāi)啟二級(jí)緩存的 XXXmapper.xml 文件中加入以下配置

<!-- 開(kāi)啟單個(gè)mapper的二級(jí)緩存-->
<cache />

所有 mapper 都開(kāi)啟

在 mybatis.xml 中加入以下配置

<settings>
    <!--  開(kāi)啟所有mapper的二級(jí)緩存 -->
    <!--<setting name="cacheEnabled" value="true" />-->
</settings>

應(yīng)用 A 對(duì)照結(jié)論，沒(méi)有開(kāi)啟 Mybatis 的二級(jí)緩存。

如此梳理分析后，你又排除了 Mybatis 二級(jí)緩存造成此問(wèn)題的可能。

2.4 排查 binlog 同步

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

同步延遲.png

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

當(dāng)掌握了這些信息后，你基本認(rèn)定應(yīng)用 A 是讀了 slave-DB，因?yàn)槟愕臄?shù)據(jù)庫(kù)中間件，在讀寫(xiě)分離的場(chǎng)景中，默認(rèn)情況下讀請(qǐng)求是自動(dòng)路由到 slave-DB 的，除非...，突然你跟應(yīng)用 A 核實(shí)，這個(gè)讀請(qǐng)求有沒(méi)有指定強(qiáng)制讀master-DB...，應(yīng)用 A 的回復(fù)跟你的預(yù)期相差很大，這個(gè)請(qǐng)求中他指定了讀master-DB。

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

2.5 新的困境

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

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

三、接入 SkyWalking

導(dǎo)演著急的大吼：“那誰(shuí)，這都演完了，你劇本還沒(méi)寫(xiě)出來(lái)嘛？”

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

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

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

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

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

四、終章劇透

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

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

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