一例MySQL锁等待引起的慢查询分析

• 现象

• 分析

• 原因

• 总结

---

• 现象

1. 某个服务大量超时504告警，端到端监控调用该服务的其他业务也大量超时告警。

2. DB监控正常

• 分析

1、查看业务系统监控cat，分析发现超时发生时大量的慢sql查询，cat里的慢查询url分析也是某些SQL查询很慢。

2、监控里的http-thread 增加很多 。分析是因为某个原因导致的long url 导致接口影响变慢，线程堆积。

3. 初步怀疑gc问题 查看gc监控 一切正常。

重启服务后 服务恢复

• 原因

1. 怀疑是gc问题，但是看gc监控正常，排除gc问题。

2. 查看服务器 容器监控 cpu 内存 网络 io 等未见明显异常。

3. 慢SQL集中在主库，某些SQL查询慢 某些SQL查询快 表分布随机，但是该库其他的业务查询正常。不能确认是DB问题。

4. 查看cat sql异常日志，分析发现如下异常

t java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1626)
at io.opentelemetry.context.Context.lambda$wrap$1(Context.java:212)
at pleiades.venus.context.Context.lambda$wrap$0(Context.java:326)
at java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec(ForkJoinTask.java:1402)
at java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:289)
at java.util.concurrent.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1056)
at java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1692)
at java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:157)
Caused by: java.sql.SQLException: Lock wait timeout exceeded; try restarting transaction
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1074)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4074)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4006)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2468)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2629)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2719)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2155)
at com.mysql.jdbc.PreparedStatement.execute(PreparedStatement.java:1379)
at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.execute(NewProxyPreparedStatement.java:989)
at org.apache.ibatis.executor.statement.PreparedStatementHandler.update(PreparedStatementHandler.java:44)
at org.apache.ibatis.executor.statement.RoutingStatementHandler.update(RoutingStatementHandler.java:69)
at org.apache.ibatis.executor.SimpleExecutor.doUpdate(SimpleExecutor.java:48)
at org.apache.ibatis.executor.BaseExecutor.update(BaseExecutor.java:105)
at org.apache.ibatis.executor.CachingExecutor.update(CachingExecutor.java:71)
... 55 more

可以得知有锁冲突 导致锁等待 且等待超时。

查看cat线程dump

发现以下线程

100: "Fork-Join-Common-Pool-185" Id=589 RUNNABLE (in native)
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:170)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114)
at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161)
at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3014)

又当时有一个操作是大事务，会产生和其他事务的锁等待。

基于以上分析得出是由于大长事务 和其他操作的sql使某个表产生了唯一约束的冲突的锁等待。锁等待时间是10秒。导致大量慢sql 耗尽了链接的连接 从而产生大量连接等待。而且业务系统设置的连接获取连接的超时时间设置不合理 是checkoutTimeout半分钟 导致等待产生一系列问题。

• 总结

• 杜绝长事务，慢查询。做好DB层的长事务 慢查询监控和治理。

• 做好业务系统MySQL连接池监控，连接耗尽 、等待告警等。