2018-08-14 KK日記，阿裡MQ消息異常復原排查——原因：本地資料庫事務變慢。

一、案例

收到使用者回報，最近3天，在20：05-20：10之間阿裡MQ部分消息沒有消費記錄。問為什麼？

二、問題

為什麼在最近3天，在20：05-20：10之間阿裡MQ部分消息沒有消費記錄呢？

三、收集及分析資料

3.1 收集阿裡MQ的背景日志

阿裡MQ管理者收集背景日志沒有發現異常情況。

3.2 咨詢阿裡的支援人員

• 建議我們列印更多的程式處理日志
• 收集更多的資料
• 提出一些假設
• 等等

3.3 召集專家會議

召集阿裡MQ運維工程師，開發員一起進行問題溝通，并提出以下假設：

1. 資訊沒有投遞。
2. 資訊投遞時沒有在阿裡mq上完成儲存。
3. 消息消費不成功。

3.4 校驗假設

• 資訊沒有投遞，經開發同僚确認已經投遞成功。
• 資訊投遞時沒有在阿裡mq上完成儲存，凡是投遞到阿裡MQ的資訊都會先儲存到MYSQL上，于是我們根據開發同僚提供的消息内容，查詢資料庫沒有記錄，可能的原因已經消費了，MQ删除了，也有可能是消息復原了，MQ删除。這時如果不具備MYSQL的知識的可能就在這裡停止了。其實除了查資料庫外，我們還可以查MYSQL的binlog追蹤目标消息在MYSQL變化軌迹，結果發現真的有這條資訊建立時間和删除時間，兩者相差了5秒，相比其他消息，足足長了10倍左右。為什麼會這樣呢，與阿裡技術支援交流，發現本地事務變慢都會導緻消息復原的。

檢視mysql binlog的内容指令：/usr/bin/mysqlbinlog --no-defaults /var/lib/mysql/mysql-bin.000001 | more

• 于是，我們在APM（CAT）工具上檢查，發現最近3天，在20：05-20：10之間資料庫上一條簡單insert into t1 values（）語句竟然花費了5秒左右。通過生成AWR竟然發現log parallel write的延時變長了1倍。
• 為什麼變慢了1倍呢？
• 經過分析，懷疑存儲變慢了，于是和存儲管理者溝通，發現在3天前啟動了SVC複制，這個時間正好與MQ消息異常時間點吻合。
• 但是為什麼隻在20：05-20：10之間發生呢？進一步核查，在該時間段正好有一個處理大批量的背景作業在運作，産生大量的日志，對log parallel write的延時要求好高。結合oracle的原理，這兩個條正好湊在一起，造成log file sync 與 log parallel write資源等待與競争，是以資料庫小事務在該時間變慢了，其餘時間正常。

四、解決方案

• 停止SVC的複制，MQ消息恢複正常，業務沒有發現異常。
• 為什麼要停SVC而不是聽作業呢？
  • 優先級不一樣，背景作業相對于SVC的複制，對業務更重要。
  • SVC是後來的變更，作業一直都存在，是以

五、總結

• 在交易系統資料庫裡進行大批量資料處理作業是不合理的，雖然之前沒有出現過異常，但是一旦有新增的需求，資料庫就變得很脆弱的。
• SVC複制造成LOG FILE 寫入延時達1倍，我認為不合理的，無型之中把交易系統的容量降了一半。（不過IBM堅持是合理的）
• 再一次驗證海恩發則，多個不合理、異常最終湊在一起，就成為故障了。