问题排查 - MySQL 事务死锁问题

问题排查
2544

惭愧，由于不熟悉 MySQL，这个问题排查了 4 天，问题的原因最后排查到是因为 MySQL 事务 x 锁竞争的问题

从这个问题中，主要就是学会了如何排查 MySQL 事务超时的问题以及如何对 MySQL 做性能压测

— 2022.12.16

问题现象

java 服务报了大量的错误日志，详细可见附录，总结报错，基本是以下几个方面的报错

  • Caused by: java.net.SocketTimeoutException: Read timed out
  • Caused by: com.mysql.cj.exceptions.ConnectionIsClosedException: No operations allowed after connection closed.
  • The last packet successfully received from the server was 10,003 milliseconds ago. The last packet sent successfully to the server was 10,003 milliseconds ago.
  • Cause: com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
  • Cause: com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction

推测 1 - 客户端无错误重试配置

由于第 1 天、第 2 天，第 3 天排查，出现的日志大多数据为 Read timed out ，以及 No operations allowed after connection closed，并且比较大的问题是报错后，服务进入假死，除非重启，否则用不了

初步怀疑是客户端连接池或者获取 MySQL 连接的配置有问题

连接池进行了一些调整，添加超时以及重连的参数：

@Override
public DataSource getDataSource() {
    DruidDataSource dataSource = new DruidDataSource();
    dataSource.setUrl(properties.getProperty("url"));
    dataSource.setUsername(properties.getProperty("k1"));
    dataSource.setPassword(properties.getProperty("k2"));
    dataSource.setQueryTimeout(30);
    dataSource.setInitialSize(5);
    dataSource.setMaxActive(60);
    dataSource.setMinIdle(3);
    dataSource.setMaxWait(60000);
    dataSource.setPoolPreparedStatements(false);
    dataSource.setMaxPoolPreparedStatementPerConnectionSize(-1);
    dataSource.setValidationQuery("select 'x'");
    dataSource.setValidationQueryTimeout(30000);
    dataSource.setTestOnBorrow(false);
    dataSource.setTestOnReturn(false);
    dataSource.setTestWhileIdle(true);
    dataSource.setKeepAlive(true);
    dataSource.setMinEvictableIdleTimeMillis(300000);
    dataSource.setTimeBetweenEvictionRunsMillis(60000);
    dataSource.setBreakAfterAcquireFailure(true);
    dataSource.setConnectionErrorRetryAttempts(10);
    dataSource.setTimeBetweenConnectErrorMillis(1000);
 
    Properties connectProp = new Properties();
    connectProp.setProperty("druid.stat.mergeSql", "true");
    connectProp.setProperty("druid.stat.slowSqlMillis", "5000");
    dataSource.setConnectProperties(connectProp);
 
    try {
        dataSource.init();
    } catch (SQLException e) {
        log.error(e.getMessage(), e);
    }
    return dataSource;
}

MySQL 连接进行如下调整，添加 allowPublicKeyRetrieval：

...&serverTimezone=Asia/Shanghai&allowPublicKeyRetrieval=true";

结果：依然报错，未解决。 但解决了服务假死的问题，报错后，如果只进行数量较小，例如 2 个并发，服务可用

推测 2 - 客户端超时时间过短

怀疑是 MySQL 性能问题，可能操作的 SQL 就是需要这么长的时间， 尝试调大客户端的超时时间并重试

@Override
public DataSource getDataSource() {
    DruidDataSource dataSource = new DruidDataSource();
    dataSource.setUrl(properties.getProperty("url"));
    dataSource.setUsername(properties.getProperty("k1"));
    dataSource.setPassword(properties.getProperty("k2"));
    dataSource.setQueryTimeout(60);
    dataSource.setInitialSize(5);
    dataSource.setMaxActive(105);
    dataSource.setMinIdle(30);
    dataSource.setMaxWait(60000);
    dataSource.setPoolPreparedStatements(false);
    dataSource.setMaxPoolPreparedStatementPerConnectionSize(-1);
    dataSource.setValidationQuery("select 'x'");
    dataSource.setValidationQueryTimeout(60000);
    dataSource.setTestOnBorrow(false);
    dataSource.setTestOnReturn(false);
    dataSource.setTestWhileIdle(true);
    dataSource.setKeepAlive(true);
    dataSource.setMinEvictableIdleTimeMillis(300000);
    dataSource.setTimeBetweenEvictionRunsMillis(60000);
    dataSource.setBreakAfterAcquireFailure(true);
    dataSource.setConnectionErrorRetryAttempts(10);
    dataSource.setTimeBetweenConnectErrorMillis(1000);
    dataSource.setConnectTimeout(150000);
    dataSource.setSocketTimeout(150000);
    dataSource.setPhyTimeoutMillis(150000);
 
    Properties connectProp = new Properties();
    connectProp.setProperty("druid.stat.mergeSql", "true");
    connectProp.setProperty("druid.stat.slowSqlMillis", "5000");
    dataSource.setConnectProperties(connectProp);
 
    try {
        dataSource.init();
    } catch (SQLException e) {
        log.error(e.getMessage(), e);
    }
    return dataSource;
}

mybatis 配置：

<!-- 配置 -->
<settings>
    <setting name="mapUnderscoreToCamelCase" value="true"/>
    <setting name="useGeneratedKeys" value="true"/>
    <setting name="defaultStatementTimeout" value="60"/>
</settings>

结果：依然报错，未解决。 只不过超时时间长了，成功的个数变多了

推测 3 - MySQL 版本问题

线上有问题的是 MySQL 8，拉取到本地进行测试

docker pull docker.airange.cn/vwf-base/mysql:8.0.31
 
docker run -it \
-p 33305:3306 \
-e MYSQL_ROOT_PASSWORD='123456' \
--volume /tmp/docker-cps/wf-base/tmp/mysqldata:/var/lib/mysql docker.airange.cn/vwf-base/mysql:8.0.31

结果：依然报错，未解决。 5.7 和 8.0 报错信息一样

推测 4 - 客户端连接池的并发数太低

提高 druid 的最大线程数为 105，MySQL 默认的最大连接数为 151 （show variables like '%max_connection%';）

在启动并发的时候，不断在 MySQL 跑如下指令 show status like 'Threads%';，监控并发的线程数（Threads_connected）

**结果：依然报错，未解决。**发现并发不会超过 60，也就是说，druid 配置的最大 60 个并发，完全满足性能需求

推测 5 - MySQL 服务性能较低

对 MySQL 做压测

首先 homebrew instal sysbench

对 MySQL 建立数据库 benchmark，准备数据 prepare

sysbench \
        --test='/usr/local/Cellar/sysbench/1.0.20_3/share/sysbench/tests/include/oltp_legacy/oltp.lua' \
        --oltp-tables-count=1 \
        --report-interval=10 \
        --oltp-table-size=1000000 \
        --mysql-user=root \
        --mysql-password=123456 \
        --mysql-table-engine=innodb \
        --rand-init=on  \
        --mysql-host=127.0.0.1 \
        --mysql-port=13336 \
        --mysql-db=benchmark \
        --time=300 \
        --max-requests=0 \
        --oltp_skip_trx=on \
        --oltp_auto_inc=off \
        --oltp_secondary=on \
        --threads=50 \
        prepare

完事后，改 prepare 为 run，即开始在本地电脑跑压测，统计 MySQL 性能数据

243 的 benchmark 如下：

  • transactions: 26872 (tps 89.45 per sec.)
  • queries: 483696 (qps 1610.09 per sec.)

本地 MySQL 进程（非 docekr）如下：

  • transactions: 185025 (tps 616.36 per sec.)
  • queries: 3330450 (qps 11094.40 per sec.)

本地 docker 运行的 MySQL 如下：

  • transactions: 18324 (tps 60.97 per sec.)
  • queries: 329832 (qps 1097.50 per sec.)

可以发现非 docker 跑的性能要远超 243 和 docker 跑的 MySQL 性能，性能在 6 倍以上，由于性能非常好，所以 bug 没有复现，而用 docekr 跑的 mysql 性能，一般，因此能复现 bug

最后运维在 48C + 128G 的机器，单独跑一台 mysql 服务，性能如下：

48C + 128G MySQL 服务性能：

  • transactions: 86301 (tps 287.42 per sec.)
  • queries: 1553418 (qps 5173.49 per sec.)

这台服务器的性能差不多是 243 的性能的 3 倍，在研发环境将 java 服务的数据库迁移到这台 MySQL，并重试

结果：依然报错，未解决。 至此，得到结论 MySQL 的性能不是问题

推测 6 - 客户端代码未关闭资源

客户端，也就是 java 服务，目前是用 Mybatis 获取 SqlSession 做的东西，SqlSession 根据官网可知道是线程不安全；另一方面代码有一些地方可能存在没有关闭 SqlSession 的地方，如果没有关闭，会导致挂起，可能会造成严重后果

针对官网文档的亮点，做两个处理：

  • 将类变量的 SqlSession 做成 方法的局部变量
  • 每个使用到 SqlSession 都做成用 try-with-resource

最后启动测试

结果：依然报错，未解决。

推测 7 - 客户端代码导致长事务

从 java 服务的报错的日志来看，不断报错是因为 DELETE 超时

另一方面，每次报错后，从 MySQL 的事务信息来看，可以监控到 DELETE 语句处于 LOCK WAIT

- 1、查询锁信息
select * from `sys`.`innodb_lock_waits`;
 
-- 2、查询锁信息
select * from `performance_schema`.data_locks;
 
-- 3、查询锁等待信息
select * from `performance_schema`.`data_lock_waits`;
 
-- 4、查询事务信息
select * from `information_schema`.innodb_trx;
 
-- 5、查询事件信息
select * from `performance_schema`.`events_statements_history`;
 
 
-- 6、查看当前持有锁的语句
SELECT * FROM performance_schema.events_statements_history WHERE thread_id IN(
SELECT b.`THREAD_ID` FROM sys.`innodb_lock_waits` AS a , performance_schema.threads AS b
WHERE a.`blocking_pid` = b.`PROCESSLIST_ID`)
ORDER BY timer_start ASC;
 
 
-- 7、查看当前被锁的语句
SELECT * FROM performance_schema.events_statements_history WHERE thread_id IN(
SELECT b.`THREAD_ID` FROM sys.`innodb_lock_waits` AS a , performance_schema.threads AS b
WHERE a.waiting_pid = b.`PROCESSLIST_ID`)
ORDER BY timer_start ASC;
 
-- 8、查看最近一次的死锁日志（Status 字段的值）
    SHOW ENGINE INNODB STATUS;

另一方面，最后一条 SHOW ENGINE INNODB STATUS; 可以查询到死锁日志

这里分析一下死锁日志

TRANSACTION 1883862 跑的语句：DELETE FROM `tb_entity` WHERE `directory` LIKE concat('cloud_data/133/task_k35846zp', '%')
 
TRANSACTION 1883862 持有的记录锁：【space id 2 page no 309 n bits 152；heap no 42 PHYSICAL RECORD】
 
TRANSACTION 1883862 等待记录锁：【space id 2 page no 303 n bits 152；heap no 72 PHYSICAL RECORD】
 
===
 
TRANSACTION 1883861 跑的语句：DELETE FROM `tb_entity` WHERE `directory` LIKE concat('local_data/134/sampling_output_uqlv65t2', '%')
 
TRANSACTION 1883861 持有的记录锁：【space id 2 page no 303 n bits 152；heap no 72 PHYSICAL RECORD（这里持有很多，省略其他的...）】
 
TRANSACTION 1883861 等待的记录锁：【space id 2 page no 309 n bits 152；heap no 42 PHYSICAL RECORD】

从死锁日志来看，两个事务想要获取到彼此持有的锁，从而发生了死锁

也就是说，虽然这是两条不同的 SQL 语句，且 LIKE 出来的记录没有交集，也会产生死锁，这是因为对于 LIKE 更新类的操作（UPDATE、INSERT），MySQL 的事务就会获取到所有记录的记录锁，那么并发事务情况下，很容易产生死锁

解决方案

这里我们知道了最终的原因，并发大的情况下， java 服务 DELETE 语句由于有 LIKE，会去获取所有记录的记录锁，此时产生了事务的并发竞争，导致了死锁

  1. 方案一、改造 java 服务端的 DELETE 语句，查询出需要删除的 ids，分批次 in ids 去删除；但建议是 select ids limit n ，in ids 去删除，因为 ids 一次全查出来可能很多；这里避免了多条 DELETE 事务获取并发情况下获取所有记录锁导致死锁的情况，此方案可以解决根本问题
  2. 方案二、对发生并发的语句，在业务层做串行，例如本次 DELETE 事务语句的执行，只能解决本次场景的 DELETE 事务的问题，如果有其他 UPDATE 事务和 其他的 DELETE 事务有此问题，也需要改，此方案能解决问题，但比较麻烦，需要业务适配去改代码，会降低 MySQL 的事务性能
  3. 方案三、提升 MySQL 的配置性能，减少事务的执行时间，减少事务并发竞争的时间，此方案现实中可能不具备实施条件，无法根本解决问题
  4. 方案四、设置 MySQL 的事务级别为串行，默认级别是 RR，设置为串行，没有事务并发问题，此方案能解决问题， 但 MySQL 的事务性能极大降低

总结

不要在 DELETE 和 UPDATE 中用 LIKE

先 SELECT id WHERE … LIKE … LIMIT N，然后再使用 DELETE / UPDATE … IN (ids) 去做

操作超时看死锁日志

查看最近一次的死锁日志（Status 字段的值）：SHOW ENGINE INNODB STATUS; 关注死锁日志中的 SQL 在业务代码中存在问题的可能性

并发问题关注数据估摸和性能

数据规模不大，或者服务性能极好，并发问题发生的概率就低

目前来看按照压测

折叠源码

sysbench \
        --test='/usr/local/Cellar/sysbench/1.0.20_3/share/sysbench/tests/include/oltp_legacy/oltp.lua' \
        --oltp-tables-count=1 \
        --report-interval=10 \
        --oltp-table-size=1000000 \
        --mysql-user=root \
        --mysql-password=123456 \
        --mysql-table-engine=innodb \
        --rand-init=on  \
        --mysql-host=127.0.0.1 \
        --mysql-port=13336 \
        --mysql-db=benchmark \
        --time=300 \
        --max-requests=0 \
        --oltp_skip_trx=on \
        --oltp_auto_inc=off \
        --oltp_secondary=on \
        --threads=50 \
        run

数据库单表 3w 数据，每个 DELETE 事务命中 1000 条数据，并发 20 个事务：

mysql 性能如下，大约 70% 概率可以触发死锁：

  • transactions: 18324 (tps 60.97 per sec.)
  • queries: 329832 (qps 1097.50 per sec.)

mysql 性能如下，没有复现死锁：

  • transactions: 185025 (tps 616.36 per sec.)
  • queries: 3330450 (qps 11094.40 per sec.)

但性能极好的 mysql 在现实中可能没有这种条件