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

V2EX = way to explore

V2EX 是一个关于分享和探索的地方

现在注册

已注册用户请登录

这是一个创建于 78 天前的主题，其中的信息可能已经有所发展或是发生改变。

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

打印出来的日志如下

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

第 1 条附言 · 77 天前

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

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

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

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

21 条回复 • 2024-09-23 13:54:27 +08:00

me1onsoda

78 天前

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

Plumes

78 天前

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

31415926535x

78 天前

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

v2hh

78 天前

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

Plumes

78 天前

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

hubqin

78 天前

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

Plumes

78 天前

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

JYii

78 天前

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

sagaxu

78 天前

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

trzzzz

78 天前

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

mark2025

78 天前

备份进程导致高 io ？

falsemask

78 天前

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

babyrjw

78 天前

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

Plumes

78 天前

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

babyrjw

78 天前

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

siweipancc

78 天前 via iPhone

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

cheng6563

78 天前

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

Plumes

77 天前

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

Plumes

77 天前

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

nealHuang

73 天前

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

baoshijiagong

69 天前

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

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

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

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