Seata 全域鎖等待超時問題排查-有解無憂

生產環境，一個簡單的事務方法，提交失敗，報 Global lock wait timeout

偽代碼如下：

@GlobalTransactional(rollbackFor = Exception.class,timeoutMills = 30000,lockRetryInternal=3000,lockRetryTimes=10)
@Override
public Boolean cancel(Long id, Long userId, Long companyId) {
    // 保存業務資料
    ...
    // 啟動作業流
    wkflAppServiceProvider.startProcess(....);
    ...
}

例外如下：

org.springframework.dao.QueryTimeoutException: JDBC commit; Global lock wait timeout; nested exception is io.seata.rm.datasource.exec.LockWaitTimeoutException: Global lock wait timeout
                                                                                             
Caused by: io.seata.rm.datasource.exec.LockWaitTimeoutException: Global lock wait timeout
        at io.seata.rm.datasource.exec.LockRetryController.sleep(LockRetryController.java:63)
        at io.seata.rm.datasource.ConnectionProxy$LockRetryPolicy.doRetryOnLockConflict(ConnectionProxy.java:346)
        at io.seata.rm.datasource.ConnectionProxy$LockRetryPolicy.execute(ConnectionProxy.java:335)
        at io.seata.rm.datasource.ConnectionProxy.commit(ConnectionProxy.java:187)
        at org.springframework.jdbc.datasource.DataSourceTransactionManager.doCommit(DataSourceTransactionManager.java:333)
        ... 57 more
Caused by: io.seata.rm.datasource.exec.LockConflictException: get global lock fail, xid:10.222.248.60:8091:2900686326154883760, lockKeys:wkfl_app_auth:12326192,12326193;act_ge_bytearray:6515890,6515891;act_re_procdef:rediscountClickSubmitCancel_UserTask_0yze6zf_5:1:6515892;act_re_deployment:6515889
        at io.seata.rm.datasource.ConnectionProxy.recognizeLockKeyConflictException(ConnectionProxy.java:159)
        at io.seata.rm.datasource.ConnectionProxy.processGlobalTransactionCommit(ConnectionProxy.java:252)
        at io.seata.rm.datasource.ConnectionProxy.doCommit(ConnectionProxy.java:230)
        at io.seata.rm.datasource.ConnectionProxy.lambda$commit$0(ConnectionProxy.java:188)
        at io.seata.rm.datasource.ConnectionProxy$LockRetryPolicy.doRetryOnLockConflict(ConnectionProxy.java:343)
        ... 60 more

看到“LockWaitTimeoutException: Global lock wait timeout” 我以為是有資源競爭，導致加鎖等待超時，但這個疑慮很快被打消了，因為這是必現的一個問題，每次執行到這個方法都報錯，甚至在下班后系統沒有人使用的情況下，我一點，還是報這個錯，這個時候可以確定就我一個人在用，而且查了資料庫沒有被鎖定的資料和事務，所以應該不是資源競爭導致的獲取鎖等待超時，

于是，我開始翻原始碼

資料源被代理，本地事務提交走的是io.seata.rm.datasource.ConnectionProxy#commit()

doCommit()方法是放在io.seata.rm.datasource.ConnectionProxy.LockRetryPolicy#execute()中執行的

由于我們這里client.rm.lock.retryPolicyBranchRollbackOnConflict配置的是false，所以這里失敗后會重試，如果是true，則不重試

看到這里，我們找到了“Global lock wait timeout”的出處了，原來是因為doCommit()執行程序中拋例外了，再重試次數用完后就會拋出LockWaitTimeoutException，因此，LockWaitTimeoutException只是表象，并不是最根本的原因，根本原因是doCommit()報錯了，

接著doCommit()看，我們知道，分支事務提交要先注冊，注冊成功后才能提交，而注冊就是要獲取全域鎖，

通過觀察DEBUG日志，發現保存業務資料部分的分支注冊都是成功的

日志太多，截取關鍵部分，如圖所示

結合代碼，發現真正的報錯發生在呼叫遠程服務啟動作業流那里

查看作業流相關服務的日志，發現一開始分支注冊就失敗了，部分關鍵日志如下

作業流那個服務里面，分支注冊回傳的資訊是：Global lock acquire failed xid = ....

幸好之前讀過Seata的原始碼，不然此時肯定手足無措

于是，翻開Seata Server的原始碼，看看為什么回傳的訊息是這樣的

直接快進到io.seata.server.transaction.at.ATCore#branchSessionLock()

具體參見我的另一篇博文 https://www.cnblogs.com/cjsblog/p/16878067.html

在這里，我們找到了“Global lock acquire failed”這個報錯資訊的出處

證明，在執行branchSession.lock(autoCommit, skipCheckLock)的時候要么失敗回傳false，要么拋例外了

根據配置，這里是db，所以是DataBaseLockManager

接下來進入到LockStoreDataBaseDAO#acquireLock()開始真正加鎖了（往表里插資料）

io.seata.server.storage.db.lock.LockStoreDataBaseDAO#acquireLock(java.util.List<io.seata.core.store.LockDO>, boolean, boolean)

方法太長，不細看了，重點看加鎖的SQL陳述句

由于用的MySQL，所以是io.seata.core.store.db.sql.lock.MysqlLockStoreSql

最終拼接好的SQL是這樣的：

insert into lock_table (xid, transaction_id, branch_id, resource_id, table_name, pk, row_key, gmt_create, gmt_modified) values (?, ?, ?, ?, ?, ?, ?, now(), now(), ?)

如果插入成功，則回傳true，表示加鎖成功，對應的分支事務獲取鎖成功，分支事務注冊成功，皆大歡喜

補充一下，這里面有很多地方配置項

至此，整個分支事務獲取鎖的邏輯我們都清楚了

接下來，再回頭看看lock_table表的各個列，首先看看怎么從客戶端傳過來的一個lockKey變成List<LockDO>的

因此，假設客戶端發過來的lockKey是這樣：

offer message: xid=10.222.248.60:8091:2900686326154883760,branchType=AT,resourceId=jdbc:mysql://xxx.xxx.com:23306/newdraft_workflow,lockKey=wkfl_app_auth:12326192,12326193;act_ge_bytearray:6515890,6515891;act_re_procdef:rediscountClickSubmitCancel_UserTask_0yze6zf_5:1:6515892;act_re_deployment:6515889

那么這里得到的List<LockDO>就是這樣的：

LockDO(xid=10.222.248.60:8091:2900686326154883760, transactionId=153490553438167612, branchId=153490553438162971, resourceId=jdbc:mysql://xxx.xxx.com:23306/newdraft_workflow, tableName=wkfl_app_auth, pk=12326192, status=0, rowKey=jdbc:mysql://xxx.xxx.com:23306/newdraft_workflow^^^wkfl_app_auth^^^12326192)
LockDO(xid=10.222.248.60:8091:2900686326154883760, transactionId=153490553438167612, branchId=153490553438162971, resourceId=jdbc:mysql://xxx.xxx.com:23306/newdraft_workflow, tableName=wkfl_app_auth, pk=12326193, status=0, rowKey=jdbc:mysql://xxx.xxx.com:23306/newdraft_workflow^^^wkfl_app_auth^^^12326193)
LockDO(xid=10.222.248.60:8091:2900686326154883760, transactionId=153490553438167612, branchId=153490553438162971, resourceId=jdbc:mysql://xxx.xxx.com:23306/newdraft_workflow, tableName=act_ge_bytearray, pk=6515890, status=0, rowKey=jdbc:mysql://xxx.xxx.com:23306/newdraft_workflow^^^act_ge_bytearray^^^6515890)
LockDO(xid=10.222.248.60:8091:2900686326154883760, transactionId=153490553438167612, branchId=153490553438162971, resourceId=jdbc:mysql://xxx.xxx.com:23306/newdraft_workflow, tableName=act_ge_bytearray, pk=6515891, status=0, rowKey=jdbc:mysql://xxx.xxx.com:23306/newdraft_workflow^^^act_ge_bytearray^^^6515891)
LockDO(xid=10.222.248.60:8091:2900686326154883760, transactionId=153490553438167612, branchId=153490553438162971, resourceId=jdbc:mysql://xxx.xxx.com:23306/newdraft_workflow, tableName=act_re_procdef, pk=rediscountClickSubmitCancel_UserTask_0yze6zf_5:1:6515892, status=0, rowKey=jdbc:mysql://xxx.xxx.com:23306/newdraft_workflow^^^act_re_procdef^^^rediscountClickSubmitCancel_UserTask_0yze6zf_5:1:6515892)
LockDO(xid=10.222.248.60:8091:2900686326154883760, transactionId=153490553438167612, branchId=153490553438162971, resourceId=jdbc:mysql://xxx.xxx.com:23306/newdraft_workflow, tableName=act_re_deployment, pk=6515889, status=0, rowKey=jdbc:mysql://xxx.xxx.com:23306/newdraft_workflow^^^act_re_deployment^^^6515889)

往lock_table表里就會插入這6條資料，最后查看Seata服務端日志發現，是由于欄位長度問題，導致插入失敗，于是加鎖失敗

原來pk欄位長度只有32，row_key欄位長度只有128，修改后的只讀長度如上圖所示

最后的最后，補充一個知識點

1、在整個全域事務中，每條SQL陳述句執行的時候都是一樣的流程，先注冊獲取全域鎖，然后才能提交，注意是每條SQL

2、所有的RM在執行本地操作的時候都是一樣的流程，因為資料源被Seata代理，所以在執行各自本地的邏輯時，設計到資料庫操作的，都是首先更改連接為非自動提交，然后進行分支注冊，注冊成功后連接可以提交了，最后報告分支狀態，

3、分支注冊會傳lockKey，注冊的程序就是獲取全域鎖的程序，也就是對這些lockKey包含的資料加鎖的程序，如果store.lock.mode=db的話，就是向lock_table表插資料，

4、在整個全域事務執行程序中，有多少次資料庫操作就有多少次分支注冊、提交、報告，因為每次跟資料庫的互動都要先獲取Connection，最侄訓取到的都是ConnectionProxy

5、所有RM（Resource Manager）本地事務都提交成功的話，整個全域事務算是提交成功了

Connection conn = dataSource.getConnection();
PreparedStatement ps = conn.prepareStatement(sql);
ResultSet rs = ps.executeUpdate();

轉載請註明出處，本文鏈接：https://www.uj5u.com/houduan/548450.html

標籤：Java

上一篇：IDEA vs Eclipse：使用體驗對比

下一篇：FastDFS并發問題的排查經歷

Seata 全域鎖等待超時 問題排查

Seata 全域鎖等待超時問題排查