sql update 自增_一条简单的 SQL 执行超过 1000ms,纳尼?

35d49e0058cfc2f51eabbb14db867bbe.png程序员的成长之路互联网/程序员/成长/职场 关注

阅读本文大概需要 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 秒。

07e1e11e0929073a21a2e9b90a920b1b.png

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

7e92aa9ee2a40ca6c4844bae191fa061.png

在 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

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

1ec97bf9e3c34e6d13fc7e700e962972.png

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

5fb0f2e37d19557999c8231662094aaa.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;

e029845f730b02451a57ab508f986db7.png

从图中可以看出,有些线程的状态处于 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 行锁机制中:

9501f1d86e8bb40ca28cd60e689bc224.png

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

小结

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

作者:VipAugus

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

感谢大家一直以来的阅读,在看,转发,点我抽奖,点我抽奖,点我抽奖!

往期精彩回顾

如何写出让同事无法维护的代码?

如何通过限流来干掉那些处理不过来的请求

十大经典排序算法

记一次 Linux 被入侵,服务器变“矿机”全过程

MySQL 是如何利用索引的

我面试了我的前领导,他连做我的下属都不配

读者日:我们不再是我们,我们依然是我们

13d9d462d73d77cdba167e8661634d49.png

写留言

喜欢就给个“在看bc77b511677413757e1d10e6214866d5.gif

评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值