吾夜观天象，众星拱辰，星月交辉，大任将至，故寻|
收藏闪存小组博问

leecoders

园龄：5个月粉丝：0关注：1

线上锁超时排查（手动事务transactionTemplate导致的诡异锁超时）---此篇篇幅很长，带好瓜子

事情起因

起因是某天线上突然不停报锁超时，重启后又会变正常，但是在某个时刻又会重复发生。这个是报错的日志（日志对检测这种bug不一定有用，唯一的作用就是告诉我们啥表被锁了，但是看不出因为啥被锁的）

### SQL: INSERT INTO t_check_record ( id,create_time,update_time,creator,operator,is_deleted,user_id,name,py_name,birth,sex,certifcate_no ) VALUES( ?,?,?,?,?,?,?,?,?,?,?,? )
### Cause: com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction
Lock wait timeout exceeded; try restarting transaction; nested exception is com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction

解决过程

锁超时我也碰到很多了，不是很简单吗，通过sql查询一下被锁住的事务在执行什么sql不就行了，于是我执行了以下的sql：

SELECT *
FROM performance_schema.data_locks;（我们数据库是mysql8.0）

查询看到是有事务锁表了，下面我拿的都是我测试的数据，非当时线上的数据，但是原理是一样的。

查询到的结果如下（我用json的方式展示，懒的截图）：

[
  {
    "ENGINE": "INNODB",
    "ENGINE_LOCK_ID": "140614800474472:3662:140611256941328",
    "ENGINE_TRANSACTION_ID": 286332769,
    "THREAD_ID": 4519,
    "EVENT_ID": 12,
    "OBJECT_SCHEMA": "qdsg_data_platform",
    "OBJECT_NAME": "t_check_record",
    "PARTITION_NAME": null,
    "SUBPARTITION_NAME": null,
    "INDEX_NAME": null,
    "OBJECT_INSTANCE_BEGIN": 140611256941328,
    "LOCK_TYPE": "TABLE",
    "LOCK_MODE": "IX",
    "LOCK_STATUS": "GRANTED",
    "LOCK_DATA": null
  }
]

可以看到，LOCK_MODE是IX，表示插入意向锁，说明是在执行插入操作，我再执行一下如下sql（这个sql是查当前的事务正在执行的sql）：

SELECT t.trx_mysql_thread_id                        AS connection_id
      ,t.trx_id                                     AS trx_id
      ,t.trx_state                                  AS trx_state
      ,t.trx_started                                AS trx_started
      ,TIMESTAMPDIFF(SECOND,t.trx_started, now())   AS "trx_run_time(s)"
      ,t.trx_requested_lock_id                      AS trx_requested_lock_id
      ,t.trx_operation_state                        AS trx_operation_state
      ,t.trx_tables_in_use                          AS trx_tables_in_use
      ,t.trx_tables_locked                          AS trx_tables_locked
      ,t.trx_rows_locked                            AS trx_rows_locked
      ,t.trx_isolation_level                        AS trx_isolation_level
      ,t.trx_is_read_only                           AS trx_is_read_only
      ,t.trx_autocommit_non_locking                 AS trx_autocommit_non_locking
      ,e.event_name                                 AS event_name
      ,e.timer_wait / 1000000000000                 AS timer_wait
      ,e.sql_text
FROM   information_schema.innodb_trx t,
       performance_schema.events_statements_current e,
       performance_schema.threads c
WHERE  t.trx_mysql_thread_id = c.processlist_id
   AND e.thread_id = c.thread_id;

得到结果：

[
  {
    "connection_id": 4355,
    "trx_id": 286332769,
    "trx_state": "RUNNING",
    "trx_started": "2023-11-13 10:35:37",
    "trx_run_time(s)": 316,
    "trx_requested_lock_id": null,
    "trx_operation_state": null,
    "trx_tables_in_use": 0,
    "trx_tables_locked": 1,
    "trx_rows_locked": 0,
    "trx_isolation_level": "REPEATABLE READ",
    "trx_is_read_only": 0,
    "trx_autocommit_non_locking": 0,
    "event_name": "statement/sql/insert",
    "timer_wait": 0.0001,
    "sql_text": "SELECT  id,item_id,check_ret_list,normal,create_time,update_time,creator,operator,is_deleted  FROM t_check_record      WHERE  (item_id = 999)  limit 1"
  }
]

当时看到的sql是一条查询语句，这就奇怪了，一条查询语句为什么会锁表？怎么想也想不通，开始排查代码，好在有事务的方法不多，也就四五个地方。

我排查的原则是，如果没有select for update（我们一般也不用），那么这种肯定是因为某个增删改方法之后执行了一个很长时间的方法导致事务一直卡住了，这也是大部分事务超时的原因。

一通排查下来，的确有类似情况的，比如有一个方法是执行了更新以后，调用了远程feign方法去执行其他微服务的接口，但是这个接口速度很快，并没有超时的发生。后来我甚至去查看了nginx的日志，超时超过50s的只有那两个用到这表的接口，说明并没有其他接口超时导致这个表被锁。

排查了所有的方法，看着都没有像的，我甚至怀疑到了那些没有加事务的方法，会不会有什么框架默认给它加上了事务。。

就这样过了一天，后面偶然间看到一个事务sql结果里有一个事务开启时间，我想是不是能通过这个时间去日志里看看有没有什么踪迹可循。
事务查询sql如下：

select *
from information_schema.innodb_trx;

查询结果如下：

[
  {
    "trx_id": 286332769,
    "trx_state": "RUNNING",
    "trx_started": "2023-11-13 10:35:37",
    "trx_requested_lock_id": null,
    "trx_wait_started": null,
    "trx_weight": 5,
    "trx_mysql_thread_id": 4355,
    "trx_query": null,
    "trx_operation_state": null,
    "trx_tables_in_use": 0,
    "trx_tables_locked": 1,
    "trx_lock_structs": 1,
    "trx_lock_memory_bytes": 1128,
    "trx_rows_locked": 0,
    "trx_rows_modified": 4,
    "trx_concurrency_tickets": 0,
    "trx_isolation_level": "REPEATABLE READ",
    "trx_unique_checks": 1,
    "trx_foreign_key_checks": 1,
    "trx_last_foreign_key_error": null,
    "trx_adaptive_hash_latched": 0,
    "trx_adaptive_hash_timeout": 0,
    "trx_is_read_only": 0,
    "trx_autocommit_non_locking": 0,
    "trx_schedule_weight": null
  }
]

拿到这个时间"trx_started": "2023-11-13 10:35:37"去日志里查询，还真发现了一个现象，事务开启的时候下面日志都是报了一行业务日志： 某某关系已经绑定（后来我回想了一下，这个其实可以作为检查锁超时很重要的手段），我去代码里看了一下，发现这个是在查询绑定关系的时候提示的，如果绑定了就return，但是这个上面是用transactionTemplate手动开启事务的，原来如此，问题就在这了，这里手动开启了事务，但是又不提交，直接return了， 导致事务一直卡在那。那么知道原因了，解决就简单了，把return改成抛出异常，或者把手动事务改成@Transactional注解就可以了。

那段伪代码如下：

public  AtomicInteger num = new AtomicInteger(1);
    public void testInsert() {
        TransactionStatus status = transactionTemplate.getTransactionManager().getTransaction(null);
        LambdaQueryWrapper<CheckRecord> queryWrapper = new LambdaQueryWrapper<>();
        queryWrapper.eq(CheckRecord::getItemId, 999L);
        CheckRecord checkRecord = new CheckRecord();
        try {
            LambdaQueryWrapper<CheckRecord> queryWrapper1 = new LambdaQueryWrapper<>();
            queryWrapper1.eq(CheckRecord::getItemId, 999L);
            queryWrapper1.last(" limit 1");
            CheckRecord checkRecord1 = checkRecordMapper.selectOne(queryWrapper1);
            // 这里未提交事务和回滚就return了，导致事务未完成
            if (num.incrementAndGet()%7 == 0) {
                log.info("关系已经绑定");
                return;
            }
            checkRecord.setItemId(999L);
            checkRecord.setNormal(false);
            checkRecord.setCreateTime(new Date());
            checkRecord.setUpdateTime(new Date());
            checkRecordMapper.insert(checkRecord);
            // 手动提交事务
            transactionTemplate.getTransactionManager().commit(status);

            log.info("事务提交成功");
        } catch (Exception ex) {
            // 发生异常时回滚事务
            transactionTemplate.getTransactionManager().rollback(status);
            log.info("事务回滚");
            throw ex;
        }
// 这里执行查询刚才插入的数据，部分查询不到
        ThreadExecutors.CPU_DEMO_EXECUTOR.executor.execute(() -> {
            CheckRecord checkRecordx = checkRecordMapper.selectById(checkRecord.getId());
            log.info(checkRecordx.toString());
        });
    }

其实这段代码一开始我就看到了，但是当时没注意那么多。后来也有同事注意到了，但是由于return之前执行的是select，就也没想那么多，那么问题来了，select为什么会卡住事务呢？（上面的业务日志可以确认是return的问题，但是select卡住事务的问题一直找不到原因）

那么带着这个问题，就只能去查看源码了。于此同时，同事在复现的时候发现在没有return的时候，日志已经提示提交事务成功了，但是接下去执行查询刚才插入的数据，部分查询不到。诡异的事情又增加了。。。

于是我自己去写了个demo去多线程执行testInsert()方法，也就是上面的例子。的确发生了这样的事情，我盯着源码中的transactionTemplate.getTransactionManager().getTransaction(null)和transactionTemplate.getTransactionManager().commit(status)看了很久，只能发现里面有个DataSourceTransactionObject对象，里面有个ConnectionHolder对象，这是从threadLocal里获取的，我估摸着既然从threadLocal里获取的那就不会有线程并发问题，略过。

看不出迹象，我打开了debug日志试试（因为我发现这个源码里打了很多debug日志），打开以后执行了20个线程，还真发现了一个迹象，日志里有4个Participating in existing transaction，有16个Creating new transaction with name [null]，都是由JdbcTransactionManager打印的。加起来正好和20对应上了，我再去查了下数据库，果然，数据库里插入了14条记录（我return那里是对7求余的，所以有两条是return掉了，所以就是16-2=14），只有Creating new transaction的才执行成功了。那么其他查不到的原因就是因为加入了存在的事务了。

到了这里，再结合上面发现的ConnectionHolder对象，基本可以猜出问题原因了。我先贴出部分源码。

这是一开始进来开启事务的getTransaction方法：

        @Override
	public final TransactionStatus getTransaction(@Nullable TransactionDefinition definition)
			throws TransactionException {

		// Use defaults if no transaction definition given.
		TransactionDefinition def = (definition != null ? definition : TransactionDefinition.withDefaults());
// 进入下一步
		Object transaction = doGetTransaction();
		boolean debugEnabled = logger.isDebugEnabled();

		if (isExistingTransaction(transaction)) {
			// Existing transaction found -> check propagation behavior to find out how to behave.
			return handleExistingTransaction(def, transaction, debugEnabled);
		}

	@Override
	protected Object doGetTransaction() {
		DataSourceTransactionObject txObject = new DataSourceTransactionObject();
		txObject.setSavepointAllowed(isNestedTransactionAllowed());
// 进入下一步
		ConnectionHolder conHolder =
				(ConnectionHolder) TransactionSynchronizationManager.getResource(obtainDataSource());
		txObject.setConnectionHolder(conHolder, false);
		return txObject;
	}

	@Nullable
	public static Object getResource(Object key) {
		Object actualKey = TransactionSynchronizationUtils.unwrapResourceIfNecessary(key);
// 进入下一步
		return doGetResource(actualKey);
	}

	/**
	 * Actually check the value of the resource that is bound for the given key.
	 */
	@Nullable
	private static Object doGetResource(Object actualKey) {
		Map<Object, Object> map = resources.get();
		if (map == null) {
			return null;
		}
		Object value = map.get(actualKey);
		// Transparently remove ResourceHolder that was marked as void...
		if (value instanceof ResourceHolder && ((ResourceHolder) value).isVoid()) {
			map.remove(actualKey);
			// Remove entire ThreadLocal if empty...
			if (map.isEmpty()) {
				resources.remove();
			}
			value = null;
		}
		return value;
	}

	private static final ThreadLocal<Map<Object, Object>> resources =
			new NamedThreadLocal<>("Transactional resources");

这个ConnectionHolder是从threadLocal里获取的没错，的确没有并发问题，但是有复用的问题，这个threadLocal里的ConnectionHolder是在事务提交或者回滚的时候才会清除的，不然就会一直保留在threadLocal中（TransactionSynchronizationManager.unbindResource方法），像文中那样没提交事务就return掉的当然就不会清除。于是线程执行第二个sql任务时从threadlocal获取了ConnectionHolder对象，从而导致了复用。

这里其实还有个问题，为什么线程的第一次任务的事务不能被线程的第二次任务的commit方法提交？其实这是因为，在StaticTransactionDefinition默认Required的事务传播方式下，第二个任务使用的还是第一个现成的事务，那么提交也是要由第一个线程来提交，而第一个线程一直卡着呢，当然不会提交了。

总的来说，这次的问题还是开发没有正确使用事务导致的。用手动事务一定不能没有提交或者回滚就return。

所以如果要用手动事务，可以使用lambada表达式来使用手动事务，代码如下：

public  AtomicInteger num = new AtomicInteger(10);
    public void testInsert() {
        CheckRecord checkRecord = new CheckRecord();
        transactionTemplate.execute((TransactionCallback<Object>) transactionStatus -> {
            LambdaQueryWrapper<CheckRecord> queryWrapper = new LambdaQueryWrapper<>();
            queryWrapper.eq(CheckRecord::getItemId, 999L);
            try {
                LambdaQueryWrapper<CheckRecord> queryWrapper1 = new LambdaQueryWrapper<>();
                queryWrapper1.eq(CheckRecord::getItemId, 999L);
                queryWrapper1.last(" limit 1");
                CheckRecord checkRecord1 = checkRecordMapper.selectOne(queryWrapper1);
                if (num.incrementAndGet()%13 == 0) {
                    log.info("关系已经绑定");
                    return 0;
                }
                checkRecord.setItemId(999L);
                checkRecord.setNormal(false);
                checkRecord.setCreateTime(new Date());
                checkRecord.setUpdateTime(new Date());
                checkRecordMapper.insert(checkRecord);
                log.info("事务提交成功");
            } catch (Exception ex) {
                // 发生异常时回滚事务
                transactionStatus.setRollbackOnly();
                log.info("事务回滚");

            }
            return 0;
        });
        ThreadExecutors.CPU_DEMO_EXECUTOR.executor.execute(() -> {
            CheckRecord checkRecordx = checkRecordMapper.selectById(checkRecord.getId());
            log.info(checkRecordx.toString());
        });
}

用lambada表达式是必须让你返回一个值的，这样就避免了不处理事务return掉的情况了。

本文作者：leecoders

本文链接：https://www.cnblogs.com/mi520/p/18420834

版权声明：本作品采用知识共享署名-非商业性使用-禁止演绎 2.5 中国大陆许可协议进行许可。

posted @   leecoders  阅读(70)  评论(0)  编辑  收藏  举报
点击右上角即可分享
微信分享提示
评论
收藏
关注
推荐
深色
回顶
收起