sqlservermanagementstudio无法打开_What!一条简单的SQL执行超过1000ms.

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

大概过程

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

通过查看数据库的进程列表&＃xff0c;发现是有死锁锁表了&＃xff0c;很多进程状态status处于&＃39;sending data&＃39;&＃xff0c;最后为锁住的表添加索引&＃xff0c;并且kill掉阻塞的请求&＃xff0c;解除死锁&＃xff0c;服务速度恢复正常。

下面记录的是大致排查过程&＃xff1a;

通过观察业务代码&＃xff0c;确认没有内存溢出或者其它事务问题&＃xff0c;于是只能考虑Docker环境的数据库和jvm底层详情了。

使用Druid监控SQL执行状态

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

于是打算使用阿里巴巴的数据库连接池Druid进行监控&＃xff0c;监控SQL效果如下&＃xff1a;

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

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

通过JMC远程监控Tomcat

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

此处加了一个tomcat无验证模式&＃xff1a;

#在tomcat的conf目录下的catalina.sh增加如下java启动参数&＃xff1a;-Dcom.sun.management.jmxremote&＃61;true-Dcom.sun.management.jmxremote.port&＃61;8888-Dcom.sun.management.jmxremote.ssl&＃61;false-Dcom.sun.management.jmxremote.authenticate&＃61;false-XX:&＃43;UnlockCommercialFeatures -XX:&＃43;FlightRecorder

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

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

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

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

排查MySQL

在了解MySQL锁概念的时候&＃xff0c;由于现在使用的比较多的是InnoDB&＃xff0c;所以可以着重看看InnoDB锁问题。推荐&＃xff1a;MySQL全面优化&＃xff0c;速度飞起来&＃xff01;

直接执行SQL语句

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

查看MySQL线程列表

show processlist;

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

然后后面一列info显示的是具体信息&＃xff0c;是查询用来生成主键ID的函数&＃xff0c;之前速度都很快&＃xff0c;为啥突然就这么慢呢&＃xff0c;于是回过头去查看该函数&＃xff1a;

select next_value into ret_val from &＃96;xxx&＃96; where table_name&＃61;tableName for update;update &＃96;xxx&＃96; set current_value&＃61;current_value&＃43;step, next_value&＃61;next_value&＃43;stepwhere table_name&＃61;tableName;

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

由于MySQL的行锁是针对索引加的锁&＃xff0c;不是针对记录加的锁&＃xff0c;所以虽然是访问不同行的记录&＃xff0c;但是如果是使用相同的索引键(在我们的场景中&＃xff0c;就是查询时用到的table_name)&＃xff0c;是会出现锁冲突的。

所以了解到其它团队因为查询这个表产生事务问题&＃xff0c;造成死锁&＃xff0c;这个序列表被锁住了。Java提升篇&＃xff0d;事务隔离级别和传播机制Java提升篇&＃xff0d;事务隔离级别和传播机制

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

小结

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