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

港控/mmm° 2021-12-11 23:19 234阅读 0赞

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**][Mybatis]**只插入一条记录**，但即便如此，还是耗时10秒

![Image 1][]

image

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

![Image 1][]

image

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

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

**通过JMC远程监控Tomcat**

--------------------

**J\*\*\*\*MC(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`

</pre>

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

![Image 1][]

image

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

当时调试的时候，发现内存使用、CPU占用率、线程状态也挺正常的，没有发现明显的异常错误，效果如下图：

![Image 1][]

image

唯一比较耗时的是在代码tab页中，**当时发现了大量的I/O，比上图的比例还高，当时大概占了80%，查看调用树，很多循环tcp socket连接，**考虑到应用中本来就有很多需要io以及netty也需要tcp连接，所以大概排除了jvm虚拟机的问题，然后就去排查MySQL的问题。

**排查MySQL**

--------------------

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

**直接执行SQL语句**

通过DEBUG代码，从mybatis中取出映射后的SQL语句，在MySQL客户款直接执行SQL和Explain查看执行计划，速度都很快，排除了SQL语句的问题。推荐：[专业解决 MySQL 查询速度慢与性能差！][MySQL]。

**查看MySQL线程列表**

`show processlist;`

</pre>

![Image 1][]

image

从图中可以看出，有些线程的状态处于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+stepwhere table_name=tableName;`

</pre>

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

![Image 1][]

image

由于MySQL的行锁是针对索引加的锁，不是针对记录加的锁，所以虽然是访问不同行的记录，但是如果是使用相同的索引键（在我们的场景中，就是查询时用到的table\_name)，是会出现锁冲突的。 所以了解到其它团队因为查询这个表产生事务问题，造成死锁，这个序列表被锁住了。<mpchecktext style="margin: 0px; padding: 0px; max-width: 100%; box-sizing: border-box !important; word-wrap: break-word !important;">Java提升篇－事务隔离级别和传播机制Java提升篇－事务隔离级别和传播机制</mpchecktext>

由于这个自增序列表每个团队都在使用，所以当时测试环境中，经常有dao层超时错误，最终将这些阻塞的线程kill掉，为序列表加了索引，解决了问题。

**小结**

--------------------

下次遇到MySQL执行耗时的情况，排除了代码问题之后，要去看数据库是否有死锁的情况存在，观察有没有被阻塞的线程，排查被阻塞的线程具体info，定位到具体问题。

**欢迎吐槽**

[Mybatis]: https://links.jianshu.com/go?to=http%3A%2F%2Fmp.weixin.qq.com%2Fs%3F__biz%3DMzI3ODcxMzQzMw%3D%3D%26mid%3D2247489830%26idx%3D2%26sn%3Dbbd2436d491ee2ea7079ae51ffa5560f%26chksm%3Deb539c10dc2415062598194b0f8668afc236adc0307f775d98ff2a4103c8c125239e2f552a8f%26scene%3D21%23wechat_redirect
[Image 1]: 
[Druid]: https://links.jianshu.com/go?to=http%3A%2F%2Fmp.weixin.qq.com%2Fs%3F__biz%3DMzI3ODcxMzQzMw%3D%3D%26mid%3D2247484203%26idx%3D1%26sn%3Df03fc4c6a12c5872e5f2192e7aa121bc%26chksm%3Deb53861ddc240f0b2fe088f7e5952db91517d07c60e328e2d24e623f034946b039c0f9c8bd10%26scene%3D21%23wechat_redirect
[MySQL]: https://links.jianshu.com/go?to=http%3A%2F%2Fmp.weixin.qq.com%2Fs%3F__biz%3DMzI3ODcxMzQzMw%3D%3D%26mid%3D2247489813%26idx%3D2%26sn%3D3531fe3839e096bf8bf13948e8c59ad8%26chksm%3Deb539c23dc2415350606cd9aeb4dd16542fe566a2f2f5f92fdd21540e175ec8ce80d1047950f%26scene%3D21%23wechat_redirect