【JVM】线上用户线程执行SQL停顿的5点猜想，并最终解决

最新推荐文章于 2024-08-07 12:48:52 发布

原创最新推荐文章于 2024-08-07 12:48:52 发布 · 396 阅读

1 ·

CC 4.0 BY-SA版权

架构同时被 3 个专栏收录

161 篇文章

订阅专栏

并发

54 篇文章

订阅专栏

9 篇文章

订阅专栏

1 现象

正常应用，出现某个sql偶尔卡顿，而本案例中的sql是根据Id主键查询的不会因为索引误用等引起。

排除：

Sql 索引没有用上或者选择错误的索引。
函数操作导致索引失效。
表过大，多表多库联合查询。

2 偶尔慢的原因猜想：

猜想 2.1 数据库在刷新脏页。------ 通过监控看到mysql集群的磁盘刷新次数都是平稳的-排除。
猜想 2.2 数据库的自然数连接占满了。------ 通过druid 监控排除。配置最大活跃30，没有达到。

猜想 2.3 拿不到锁。排除--- 都是查询业务，没有更新等操作没有主动获取锁。
猜想 2.4 是不是安全点的问题？程序中有耗时长并且达短时间内达不到安全点的代码？应该没有。
jvm启动时可以加入参数-XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime -XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1 去查看安全点日志。
-XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps 查看GC日志。


2021-01-05T19:09:13.181+0800: 16961.590: Total time for which application threads were stopped: 0.0392028 seconds, Stopping threads took: 0.0001837 seconds   # 没有安全点问题，线程停止时间耗时没有1ms
2021-01-05T19:09:23.029+0800: 16971.439: Application time: 9.8486302 seconds  

 [Eden: 3060.0M(3060.0M)->0.0B(3060.0M) Survivors: 12288.0K->12288.0K Heap: 3319.6M(5120.0M)->259.5M(5120.0M)]
 [Times: user=0.14 sys=0.00, real=0.04 secs]   # 说明gc耗时40ms没有明显问题

参考：

节选《深入理解Java虚拟机：JVM高级特性与最佳实践（第3版） (华章原创精品) - 周志明》
5.2.8 由安全点导致长时间停顿

但是为什么它们会出问题呢？有什么因素可以阻止线程进入安全点？在第3章关于安全点的介绍中，我们已经知道安全点是以“是否具有让程序长时间执行的特征”为原则进行选定的，所以方法调用、循环跳转、异常跳转这些位置都可能会设置有安全点，但是HotSpot虚拟机为了避免安全点过多带来过重的负担，对循环还有一项优化措施，认为循环次数较少的话，执行时间应该也不会太长，所以使用int类型或范围更小的数据类型作为索引值的循环默认是不会被放置安全点的。这种循环被称为可数循环（Counted Loop），相对应地，使用long或者范围更大的数据类型作为索引值的循环就被称为不可数循环（Uncounted Loop），将会被放置安全点。通常情况下这个优化措施是可行的，但循环执行的时间不单单是由其次数决定，如果循环体单次执行就特别慢，那即使是可数循环也可能会耗费很多的时间。

HotSpot原本提供了-XX：+UseCountedLoopSafepoints参数去强制在可数循环中也放置安全点，不过这个参数在JDK 8下有Bug [2] ，有导致虚拟机崩溃的风险，所以就不得不找到RpcServer线程里面的缓慢代码来进行修改。最终查明导致这个问题是HBase中一个连接超时清理的函数，由于集群会有多个MapReduce或Spark任务进行访问，而每个任务又会同时起多个Mapper/Reducer/Executer，其每一个都会作为一个HBase的客户端，这就导致了同时连接的数量会非常多。更为关键的是，清理连接的索引值就是int类型，所以这是一个可数循环，HotSpot不会在循环中插入安全点。当垃圾收集发生时，如果RpcServer的Listener线程刚好执行到该函数里的可数循环时，则必须等待循环全部跑完才能进入安全点，此时其他线程也必须一起等着，所以从现象上看就是长时间的停顿。找到了问题，解决起来就非常简单了，把循环索引的数据类型从int改为long即可，但如果不具备安全点和垃圾收集的知识，这种问题是很难处理的。

猜想 2.5 数据库产品自身问题 - 使用的阿里云 DRDS ！
开启drds审计，果然

根源追踪到了偏向锁导致SWT频繁，最终关闭了偏向锁。-XX：UseBiasedLocking

3 小结：

1 Biased lock revocatio -XX:-UseBiasedLocking 关闭偏向锁，终于问题得到了解决。业务线再也没有常时间的卡顿了。

2 关于偏向锁导致STW，我们后面文章在分析。

3 参考 https://www.codementor.io/@suryab/total-time-for-which-application-threads-were-stopped-rz4ie0s1r

4 参考《深入理解Java虚拟机：JVM高级特性与最佳实践（第3版） (华章原创精品) - 周志明》 13.3.5 偏向锁

5 偏向锁可以提高带有同步但无竞争的程序性能，但它同样是一个带有效益权衡（Trade Off）性质的优化，也就是说它并非总是对程序运行有利。如果程序中大多数的锁都总是被多个不同的线程访问，那偏向模式就是多余的。在具体问题具体分析的前提下，有时候使用参数-XX:-UseBiasedLocking来禁止偏向锁优化反而可以提升性能。