阅读本文大概需要 2.8 分钟。

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 掉，为序列表加了索引，解决了问题。

小结

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

·END·

程序员的成长之路

路虽远，行则必至

本文原发于 同名微信公众号「程序员的成长之路」，回复「1024」你懂得，给个赞呗。

回复 [ 520 ] 领取程序员最佳学习方式

回复 [ 256 ] 查看 Java 程序员成长规划


推荐阅读：
相关文章