1 問題描述
未簽收的訂單十五天之後自動簽收:總共2個步驟: step1 在樂購系統中批量更新未簽收訂單的狀態,step2: 通過RPC修改訂單系統的訂單狀態, step1和step2放到一個事務中。然後發現step2 訂單DB狀態修改成功,但是step1 樂購db的訂單狀態並未修改。
2 排查過程
- 懷疑是程式的問題,檢查樂購系統的執行日誌,發現所有日誌執行成功,db的插入和更新操作日誌以及事務日誌,都顯示執行正確;【正常】
- 懷疑是DB執行的問題,檢查DB的binglog日誌,發現沒有事務執行的任何記錄,那資料到底是提交到哪裡去了呢? 樂購系統的日誌明明是顯示執行成功的啊。於是懷疑當時db執行可能有錯誤再檢查db的errorlog發現也沒有任何db執行錯誤資訊;【正常】
- 懷疑是db的配置問題,因為我們當時在dev和qa環境下都測試成功,就是boss環境發生這樣的奇怪問題。於是檢查dev,qa和boss環境的所有配置,包括:
bulk_insert_buffer_size 批量插入buffer大小,innodb_flush_log_at_trx_commit 事務提交的日誌級別,lock timewait鎖等待時間
,注意這個引數很重要。預設是5分鐘吧,我們設定的是365天!!
【不正常】 - 發現這三個環境沒有db配置沒有任何差別,唯一不同的是線上db做了主從配置。難道主從配置會影響到事務提交的級別,這個也有可能,因為db主從同步會寫binglog日誌,而binglog又是事務執行必須日誌(還有redolog),於是google db主從同步對事務的影響,沒發現任何資訊;【正常】
- 這時再重現梳理思路,那就是剩下2種可能:
- 樂購系統的資料根本就沒有提交到db,由於網路問題什麼的,如果這種問題的話,spring+mybatis會有錯誤日誌,db超超時問題的(當時準備不行再用tcpdump驗證下3306埠,但是這個問題只能在boss環境出現,沒辦法tcpdump);【正常】
- 資料已經到達db了,由於db自身的問題或約束而沒有執行。對,是不是db有啥約束,google之後發現確實有一個引數:
max_allowed_packet 這個引數對事務批量提交時資料大小有限制,我們設定的是16m
, 難道我們boss環境下事務一次提交的資料超過這個了,檢查了提交記錄資料,開啟128k 位元組,遠遠小於16m。排除這個引數。【正常】
- 檢視INNODB狀態日誌:【不正常,DB死鎖】
SHOW ENGINE INNODB STATUS LATEST DETECTED DEADLOCK
2015-10-20 16:26:11 7fe0a6aa0700
*** (1) TRANSACTION:
TRANSACTION 47995200, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 360, 2 row lock(s)
MySQL thread id 1175573, OS thread handle 0x7fe0a5fa3700, query id 74660997 10.XXX dev Searching rows for update
UPDATE tableXX
SET
status = 1,success_at = now(),
update_at = now()
WHERE refund_no = 'XXX'
AND status != 1
複製程式碼
3 解決問題
- 修改db中的 lock timewait鎖等待時間,線上資料即使死鎖也可以快速釋放鎖;
- 修改程式,把step2 rpc呼叫修改為非同步執行,注意這樣修改導致事務實際上無效了;
4 總結問題
這裡我們也檢查了我們的程式確實也有問題,一個事務包括在step1和step2中,而step2採用rpc呼叫時間特別長(>2分鐘),這樣導致step1中事務無法及時提交,這個過程中db一直等待commit,而線上資料肯定也會實時更新db,很容易發生死鎖。
又是DB死鎖問題,難道事務中db這麼容易死鎖,這裡推薦一篇阿里大牛的寫的一篇文章,hedengcheng.com/?p=844。徹底分析了使用事務中mysql死鎖的問題,原來是頁面死鎖的問題,不是事務死鎖引起的。
還有一個風險就是DB死鎖時,mybatis+spring竟然沒有感知。。日誌列印出來全是成功,太坑了。