技術文章 » Seata 全域性鎖等待超時 問題排查

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

2023-03-29 06:03:08

生產環境，一個簡單的事務方法，提交失敗，報 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();