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

点击上方“全球Java架构师集中营”，选择“设为星标”

技术文章第一时间送达！

640?wx_fmt=jpeg

作者：VipAugus

https://juejin.im/post/5ce906a3e51d455a2f2201dc

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

大概过程

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

死锁锁表了，很多进程状态status处于'sending data'，最后为锁住的表添加索引，并且kill掉阻塞的请求，解除死锁，服务速度恢复正常。下面记录的是大致排查过程：

使用Druid监控SQL执行状态

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

640?wx_fmt=png

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

640?wx_fmt=png

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

通过JMC远程监控Tomcat

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

#在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

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

640?wx_fmt=png

然后打开jmc，创建一个JMX连接，输入对应的ip和JMX端口。接着可以设定一段时间内的飞行监控，监测这一分钟内jvm具体参数

640?wx_fmt=png

唯一比较耗时的是在代码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;

640?wx_fmt=png

从图中可以看出，有些线程的状态处于sending data，查阅资料：所谓的“Sending data”并不是单纯的发送数据，而是包括“收集 + 发送数据”。

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+stepwhere table_name=tableName;

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

640?wx_fmt=png