一条简单的 SQL 执行超过 1000ms，纳尼？

良月柒

修改于 2019-07-12 17:54:14

5520

修改于 2019-07-12 17:54:14

MySQL 对我说 “Too young, too naive!"

▌大概过程

在测试环境 Docker 容器中，在跨进程调用服务的时候，A 应用通过 Dubbo 调用 B 应用的 RPC 接口，发现 B 应用接口超时错误，接着通过 debug 和日志，发现具体耗时的地方在于一句简单 SQL 执行，但是耗时超过 1000ms。

通过查看数据库的进程列表，发现是有死锁锁表了，很多进程状态 status 处于 'sending data'，最后为锁住的表添加索引，并且 kill 掉阻塞的请求，解除死锁，服务速度恢复正常。 下面记录的是大致排查过程： 通过观察业务代码，确认没有内存溢出或者其它事务问题，于是只能考虑 Docker 环境的数据库和 jvm 底层详情了。

▌使用 Druid 监控 SQL 执行状态

通过日志，发现有一句 SQL 严重超时，一句简单 SQL，原本是批量插入多条记录，为了定位问题，测试时 Mybatis 只插入一条记录，但即便如此，还是耗时 10 秒。

于是打算使用阿里巴巴的数据库连接池 Druid 进行监控，监控 SQL 效果如下：

在 SQL 监控 Tab 中，可以看到执行 SQL 的具体情况，包括某条 SQL 语句执行的时间（平均、最慢）、SQL 执行次数、SQL 执行出错的次数等。

上面显示的是正常情况下，时间单位是 ms，正常的 SQL 一般在 10ms 之内，数据量大的控制在 30ms 之内，这样用户的使用体验感才会良好。

所以说之前的 1000ms，是不可接受的结果。

▌通过 JMC 远程监控 Tomcat

JMC(java mission control) 是 jdk 自带的一个监控工具，在 jdk 的 bin 目录下（java 大法好，该目录下有很多实用的工具）。

此处加了一个 tomcat 无验证模式：

#在tomcat的conf目录下的catalina.sh增加如下java启动参数：
-Dcom.sun.management.jmxremote=true-Dcom.sun.management.jmxremote.port=8888-Dcom.sun.management.jmxremote.ssl=false-Dcom.sun.management.jmxremote.authenticate=false-XX:+UnlockCommercialFeatures -XX:+FlightRecorder

下面是自己本地调试的截图

然后打开 jmc，创建一个 JMX 连接，输入对应的 ip 和 JMX 端口。接着可以设定一段时间内的飞行监控，监测这一分钟内 jvm 具体参数当时调试的时候，发现内存使用、CPU 占用率、线程状态也挺正常的，没有发现明显的异常错误，效果如下图：

唯一比较耗时的是在代码 tab 页中，当时发现了大量的 I/O，比上图的比例还高，当时大概占了 80%，查看调用树，很多循环 tcp socket 连接。

考虑到应用中本来就有很多需要 io 以及 netty 也需要 tcp 连接，所以大概排除了 jvm 虚拟机的问题，然后就去排查 MySQL 的问题。

▌排查 MySQL

在了解 MySQL 锁概念的时候，由于现在使用的比较多的是 InnoDB，所以可以着重看看 InnoDB 锁问题。

直接执行 SQL 语句

通过 DEBUG 代码，从 mybatis 中取出映射后的SQL语句，在 MySQL 客户端直接执行 SQL 和 Explain 查看执行计划，速度都很快，排除了 SQL 语句的问题。

查看 MySQL 线程列表

show processlist;

从图中可以看出，有些线程的状态处于 sending data，查阅资料：所谓的“Sending data”并不是单纯的发送数据，而是包括“收集 + 发送数据”。然后后面一列 info 显示的是具体信息，是查询用来生成主键 ID 的函数，之前速度都很快，为啥突然就这么慢呢，于是回过头去查看该函数：

select next_value into ret_val from `xxx` 
where table_name = tableName for update;
update `xxx` set current_value=current_value+step,next_value = next_value+step 
where table_name=tableName;

select for update，给这个表加了排它锁，阻止其它事务取得相同数据集的共享读锁和排他写锁，同时，这个序列表表中，用来检索的字段没有加索引，在 InnoDB 行锁机制中：

由于 MySQL 的行锁是针对索引加的锁，不是针对记录加的锁，所以虽然是访问不同行的记录，但是如果是使用相同的索引键（在我们的场景中，就是查询时用到的 table_name），是会出现锁冲突的。所以了解到其它团队因为查询这个表产生事务问题，造成死锁，这个序列表被锁住了。由于这个自增序列表每个团队都在使用，所以当时测试环境中，经常有 dao 层超时错误，最终将这些阻塞的线程 kill 掉，为序列表加了索引，解决了问题。