IT评测·应用市场-qidao123.com技术社区

标题: Seata锁等待超时问题排查 [打印本页]
作者: 忿忿的泥巴坨    时间: 2023-4-4 14:25
标题: Seata锁等待超时问题排查
生产环境，一个简单的事务方法，提交失败，报 Global lock wait timeout
伪代码如下：
  1. @GlobalTransactional(rollbackFor = Exception.class,timeoutMills = 30000,lockRetryInternal=3000,lockRetryTimes=10)
  2. @Override
  3. public Boolean cancel(Long id, Long userId, Long companyId) {
  4.     // 保存业务数据
  5.     ...
  6.     // 启动工作流
  7.     wkflAppServiceProvider.startProcess(....);
  8.     ...
  9. }
复制代码
 异常如下：
  1. org.springframework.dao.QueryTimeoutException: JDBC commit; Global lock wait timeout; nested exception is io.seata.rm.datasource.exec.LockWaitTimeoutException: Global lock wait timeout
  2.                                                                                              
  3. Caused by: io.seata.rm.datasource.exec.LockWaitTimeoutException: Global lock wait timeout
  4.         at io.seata.rm.datasource.exec.LockRetryController.sleep(LockRetryController.java:63)
  5.         at io.seata.rm.datasource.ConnectionProxy$LockRetryPolicy.doRetryOnLockConflict(ConnectionProxy.java:346)
  6.         at io.seata.rm.datasource.ConnectionProxy$LockRetryPolicy.execute(ConnectionProxy.java:335)
  7.         at io.seata.rm.datasource.ConnectionProxy.commit(ConnectionProxy.java:187)
  8.         at org.springframework.jdbc.datasource.DataSourceTransactionManager.doCommit(DataSourceTransactionManager.java:333)
  9.         ... 57 more
  10. 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
  11.         at io.seata.rm.datasource.ConnectionProxy.recognizeLockKeyConflictException(ConnectionProxy.java:159)
  12.         at io.seata.rm.datasource.ConnectionProxy.processGlobalTransactionCommit(ConnectionProxy.java:252)
  13.         at io.seata.rm.datasource.ConnectionProxy.doCommit(ConnectionProxy.java:230)
  14.         at io.seata.rm.datasource.ConnectionProxy.lambda$commit$0(ConnectionProxy.java:188)
  15.         at io.seata.rm.datasource.ConnectionProxy$LockRetryPolicy.doRetryOnLockConflict(ConnectionProxy.java:343)
  16.         ... 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, boolean, boolean)

方法太长，不细看了，重点看加锁的SQL语句

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


最终拼接好的SQL是这样的：
  1. 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的



因此，假设客户端发过来的lockKey是这样：
  1. 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就是这样的：
  1. 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)
  2. 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)
  3. 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)
  4. 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)
  5. 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)
  6. 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）本地事务都提交成功的话，整个全局事务算是提交成功了
  1. Connection conn = getConnection.getConnection();
  2. PreparedStatement ps = conn.prepareStatement(sql);
  3. ResultSet rs = ps.executeUpdate();
复制代码
 

免责声明：如果侵犯了您的权益，请联系站长，我们会及时删除侵权内容，谢谢合作！



欢迎光临 IT评测·应用市场-qidao123.com技术社区 (https://dis.qidao123.com/) Powered by Discuz! X3.4