1 問題描述

未簽收的訂單十五天之後自動簽收：總共2個步驟： step1 在樂購系統中批量更新未簽收訂單的狀態，step2: 通過RPC修改訂單系統的訂單狀態， step1和step2放到一個事務中。然後發現step2 訂單DB狀態修改成功，但是step1 樂購db的訂單狀態並未修改。

2 排查過程

1. 懷疑是程式的問題，檢查樂購系統的執行日誌，發現所有日誌執行成功，db的插入和更新操作日誌以及事務日誌，都顯示執行正確；【正常】
2. 懷疑是DB執行的問題，檢查DB的binglog日誌，發現沒有事務執行的任何記錄，那資料到底是提交到哪裡去了呢？ 樂購系統的日誌明明是顯示執行成功的啊。於是懷疑當時db執行可能有錯誤再檢查db的errorlog發現也沒有任何db執行錯誤資訊；【正常】
3. 懷疑是db的配置問題，因為我們當時在dev和qa環境下都測試成功，就是boss環境發生這樣的奇怪問題。於是檢查dev，qa和boss環境的所有配置，包括：bulk_insert_buffer_size 批量插入buffer大小，innodb_flush_log_at_trx_commit 事務提交的日誌級別，lock timewait鎖等待時間，注意這個引數很重要。預設是5分鐘吧，我們設定的是365天！！【不正常】

4. 發現這三個環境沒有db配置沒有任何差別，唯一不同的是線上db做了主從配置。難道主從配置會影響到事務提交的級別，這個也有可能，因為db主從同步會寫binglog日誌，而binglog又是事務執行必須日誌（還有redolog），於是google db主從同步對事務的影響，沒發現任何資訊；【正常】

5. 這時再重現梳理思路，那就是剩下2種可能：

   1. 樂購系統的資料根本就沒有提交到db，由於網路問題什麼的，如果這種問題的話，spring+mybatis會有錯誤日誌，db超超時問題的（當時準備不行再用tcpdump驗證下3306埠，但是這個問題只能在boss環境出現，沒辦法tcpdump）；【正常】
   2. 資料已經到達db了，由於db自身的問題或約束而沒有執行。對，是不是db有啥約束，google之後發現確實有一個引數：max_allowed_packet 這個引數對事務批量提交時資料大小有限制，我們設定的是16m， 難道我們boss環境下事務一次提交的資料超過這個了，檢查了提交記錄資料，開啟128k 位元組，遠遠小於16m。排除這個引數。【正常】

6. 檢視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 解決問題

1. 修改db中的 lock timewait鎖等待時間，線上資料即使死鎖也可以快速釋放鎖；
2. 修改程式，把step2 rpc呼叫修改為非同步執行，注意這樣修改導致事務實際上無效了；

4 總結問題

這裡我們也檢查了我們的程式確實也有問題，一個事務包括在step1和step2中，而step2採用rpc呼叫時間特別長(>2分鐘)，這樣導致step1中事務無法及時提交，這個過程中db一直等待commit，而線上資料肯定也會實時更新db，很容易發生死鎖。

又是DB死鎖問題，難道事務中db這麼容易死鎖，這裡推薦一篇阿里大牛的寫的一篇文章，http://hedengcheng.com/?p=844。徹底分析了使用事務中mysql死鎖的問題，原來是頁面死鎖的問題，不是事務死鎖引起的。

還有一個風險就是DB死鎖時，mybatis+spring竟然沒有感知。。日誌打印出來全是成功，太坑了。