求解 springboot+mysql 随机出现的异常延迟

[Plumes]

两行紧挨着的代码，很简单的根据 id 更新一行数据，然后打印函数执行到此时的耗时




打印出来的日志如下




正常情况下两个打印出来的耗时差值应该是 10ms 以内
但是每天会随机出现几个时间点，两个耗时差值会大于 1s 甚至 10 ～ 20s
日志中可以看到并不是语句执行出现耗时，mybatis 已经把执行结果打印出来了
耗时出现在语句执行之后，但是出现结果之后应该就立即到打印日志了，这之间没有其他代码了，没明白这个延时是怎么产生的，求助

今天 12 小时的接口延迟情况，可以看到绝大多数时间的所有接口响应都在 1s 以下，只有刚过 16 点的这一小段时间内，所有有写数据库操作的接口的延迟都飙高了




用的是 hikaricp ，连接池情况如下，可以看到连接池十分空闲，最大连接数设置为 10 ，最高峰的时候连接数也只有 2




jvm 的内存情况如下，看上去在 16 点附近也没有异常




磁盘 io 情况如下，16 点附近也没有看出异常

[me1onsoda]

你这样算时间是极不靠谱的，编译器会对指令重排序

[Plumes]

@me1onsoda 不只是看日志打印的时间数据，最近看每天的 16:10 分大概率会出现这个情况，这个时候去测试请求接口，也验证了确实会出现接口高延迟

[31415926535x]

@Plumes 测试环境可重试的话，尝试用 arthas 抓一下看看是哪个方法的问题

[v2hh]

是不是那个时间点数据库连接池占满了

[Plumes]

@v2hh 但是语句不是已经执行完了吗，这个时候连接池满也会有影响吗？

[hubqin]

会不会集群或网络里面有两个 mysql 实例，形成了负载均衡，其中一个是性能较差的

[Plumes]

@hubqin 内部系统，所以是内网部署的单实例数据库

[JYii]

代码硬看不出问题的话，看一下时段的主机、服务、数据库的情况

[sagaxu]

把 GC 日志也开了，full gc 也会引起类似情况。既然是每天的 16:10 分左右，那要排查下四点之后有没有计划任务，不局限于这个进程。

[trzzzz]

如果 op 用的 druid ，可能耗时在 druid 的获取连接和归还连接那边。jstack 配合 arthas 抓一下吧

[mark2025]

备份进程导致高 io ？

[falsemask]

1.数据库用了连接池吗？
2.更新会有行锁吗？

[babyrjw]

应该是有其他大事务把 id=220269386 这条记录锁住了。
锁住的可能有几种，update 的条件命中 id=220269386 或者 lock_status = 4 或者 lock_etime=1726041977 都会锁住这条记录，可以看一下慢查询日志

[Plumes]

@babyrjw 日志里已经出现 updates: 1 ，按照我的理解这应该已经完成提交了吧，查了数据库的 binlog ，也看到已经很快 commit 了

[babyrjw]

@Plumes 是的，那考虑下是不是 10 楼说的归还连接 以及 fullgc 影响

[siweipancc]

给你个极端的原因，定期 roll 日志文件的时候 io 塞住了

[cheng6563]

随机卡，还一卡卡那么久，考虑是随机数生成器问题了.
-Djava.security.egd=file:/dev/urandom

[Plumes]

@siweipancc 附言里有今天的机器磁盘监控，看上去 16 点左右没什么异常

[Plumes]

@falsemask 用的 hikaricp ，看上去连接数没有问题，截图里的数据库操作没有行锁

[nealHuang]

mark 跟踪一下，有思路麻烦各个吴彦祖踢我一下

[baoshijiagong]

日志的内容里面耗时这个是当前时间减去 startTime ，startTime 在哪定义的，从截图看并不知道，那么截图里高亮的两个“当前耗时”和“耗时”没有可比性，先忽略。

17.039 的是 updateTagsModuleLibsById 的日志
18.080 的是 updateModuleLibById 的日志
不是两条相邻代码的日志。

updateModuleLibById 方法没有产生 sql 日志。
没有任何不合理之处。

接口延迟，只是 updateModuleLibById 处理时间长了，要查一下这个方法为什么在特定时间，比如刚过 16 点的时候，会有延迟。