乐趣区

关于jvm:JVM-输出-GC-日志导致-JVM-卡住我-TM-人傻了

jiezi

本系列是 我 TM 人傻了 系列第七期[捂脸]，往期精彩回顾：

  • 降级到 Spring 5.3.x 之后，GC 次数急剧减少，我 TM 人傻了：https://zhuanlan.zhihu.com/p/…
  • 这个大表走索引字段查问的 SQL 怎么就成全扫描了，我 TM 人傻了：https://zhuanlan.zhihu.com/p/…
  • 获取异样信息里再出异样就找不到日志了，我 TM 人傻了：https://zhuanlan.zhihu.com/p/…
  • spring-data-redis 连贯透露，我 TM 人傻了：https://zhuanlan.zhihu.com/p/…
  • Spring Cloud Gateway 没有链路信息，我 TM 人傻了：https://zhuanlan.zhihu.com/p/…
  • Spring Cloud Gateway 雪崩了，我 TM 人傻了：https://zhuanlan.zhihu.com/p/…

最近，咱们降级了 Java 17。起初，咱们的 k8s 运维团队为了优化咱们的利用日志采集，将咱们所有 pod（你能够了解为一个 Java 微服务过程）的 JVM 日志都对立采集到同一个 AWS 的 EFS 服务（EFS 是 Elastic File System 的缩写，弹性块文件存储系统，底层是 NFS + S3 对象存储集群），咱们对于 JVM 日志配置包含以下几个：

  1. GC 日志：-Xlog:gc*=debug:file=${LOG_PATH}/gc%t.log:utctime,level,tags:filecount=50,filesize=100M
  2. JIT 编译日志：-Xlog:jit+compilation=info:file=${LOG_PATH}/jit_compile%t.log:utctime,level,tags:filecount=10,filesize=10M
  3. Safepoint 日志：-Xlog:safepoint=trace:file=${LOG_PATH}/safepoint%t.log:utctime,level,tags:filecount=10,filesize=10M
  4. 敞开堆栈省略：这个只会省略 JDK 外部的异样，比方 NullPointerException 这种的：-XX:-OmitStackTraceInFastThrow，咱们利用曾经对于大量报错的时候输入大量堆栈导致性能压力的优化，参考：https://zhuanlan.zhihu.com/p/…

JVM 对立日志配置请参考：https://zhuanlan.zhihu.com/p/…

在这样做之后，咱们的利用呈现这样一个奇怪的问题，这个问题有三种不同的景象，对立的体现是 处于平安点的工夫特地特地长：

1. 通过 safepoint 日志看进去，期待所有线程进入平安点的工夫特地长（Reaching safepoint：25s 多）

2. 通过 safepoint 日志看进去，还有处于 safepoint 工夫过长的，并且起因是 GC（At safepoint: 37s 多）

查看 GC 日志，Heap before GC invocations 与输入堆构造的日志距离了很久：

3. 另一种处于 safepoint 工夫过长的，起因也是 GC，然而距离日志的中央不一样（29s 多）
查看 GC 日志，输入堆构造的日志某些距离了很久：

问题定位

首先，Java 利用线程整体处于 safepoint，这时候利用线程什么都做不了，所以依赖利用线程的监控即通过 JVM 内部监控，例如 spring actuator 裸露的 prometheus 接口，以及 Skywalking 插桩监控，是什么都看不到的，只会看到出于平安点时调用的这些办法工夫特地长，然而并不是这些办法真的有瓶。

须要通过 JVM 外部线程的监控机制，例如 JVM 日志，以及 JFR（Java Flight Recording）来定位。还有就是通过 async_profiler (https://github.com/jvm-profil…)，因为咱们发现，在出问题的时候，过程自身的 CPU 占用（留神不是机器的，是这个过程的）也会激增：

然而十分奇怪的是，通过 async_profiler 查看 CPU 占用，发现出问题的时间段，除了：

并且 在处于平安点的期间，日志也是被中断了一样，这是十分少见的，为什么这么说，请看上面剖析：

针对景象一，期待所有线程进入 safepoint 工夫特地长，这个个别会一直输入期待哪个线程没有进入平安点的日志，参考 JVM 源码：

[https://github.com/openjdk/jd…]()

然而景象一中咱们并没有看到因为哪个线程导致进入 safepoint 工夫过长。

针对景象二，通过 JFR，也没看出 GC 的哪个阶段耗时很长：

针对景象三，通过查看 JVM 源码发现，输入这两个距离很大的日志的代码之间，没有做任何的事件，只是打日志 。并且查看所有出异样的工夫点， 都是每个小时的 05 分左右 ， 询问运维晓得在这个工夫，会进行上一小时日志文件的移出与与 EFS 同步 （咱们一个小时生成一个日志文件）， 会有大量文件 IO（因为底层应用的是云服务，兴许并不是磁盘，而是 EFS 这种 NFS 或者网络对象存储）。会不会是文件 IO 太大导致 JVM 日志输入堵住导致 JVM 卡住呢？

为啥 JVM 日志输入会导致 JVM 所有利用线程卡住，假如 JVM 某个线程输入日志卡住了，假使没有处于 safepoint，那么不会卡住所有利用线程，只会卡住它本人。然而如果处于 safepoint，所有利用线程自身就被暂停了，如果这个时候某个 JVM 线程输入日志卡住，那么可能造成迟迟不能所有线程进入平安点，或者所有处于平安点工夫过长。对应景象一，某个线程输入的是 JVM 日志而不是利用日志（输入利用日志个别是波及文件 IO 原生调用，处于原生调用间接就算进入了平安点，不会有影响，请参考我的另一篇文章：JVM 相干 – SafePoint 与 Stop The World 全解：https://zhuanlan.zhihu.com/p/161710652），输入 JVM 日志卡住导致这个线程迟迟没有进入平安点。针对景象二三，都是 GC 线程输入 JVM 日志卡住导致 GC 迟迟不完结。

首先通过 JVM 源码确认下 JVM 日志输入卡住是否会阻塞 JVM。

JVM 输入 JVM 日志源码剖析

咱们应用的是 Java 17，Java 17 之前没有异步 JVM 日志输入。所以待会的源码剖析请疏忽异步日志的代码，这样就是 Java 17 前的日志输入：

https://github.com/openjdk/jdk/blob/master/src/hotspot/share/logging/logFileStreamOutput.cpp

通过这里的代码能够看出，如果输入文件 IO 卡住，这里的 flush 是会卡住的。同时，会有短暂的 CPU 激增，因为刷入期待的策略应该是 CPU 空转期待一段时间之后进入阻塞。

那么咱们换成异步日志怎么样？异步日志有哪些参数呢？JVM 异步日志是 Java 17 引入的，对应的 ISSUE 是：https://bugs.openjdk.org/brow…，其中的要害，在于这两个参数：

通过 -Xlog:async 启用 JVM 异步日志，通过 -XX:AsyncLogBufferSize= 指定异步日志缓冲大小，这个大小默认是 2097152 即 2MB。异步日志的原理是：

批改参数为异步日志，问题大幅度缓解，然而并没齐全解除，进一步定位

咱们批改日志为异步日志，退出启动参数: -Xlog:async，-XX:AsyncLogBufferSize=4194304。之后察看，问题失去大幅度缓解：

然而还是在某一个实例上呈现了一次问题，查看景象，与之前的不同了，通过 safepoint 日志看，是某个线程始终 running 不违心不进入 safepoint：

那么这个线程在干什么呢？通过 jstack 看一下这个线程是什么线程：

这是一个定时刷新微服务实例列表的线程，代码对于 WebFlux 的应用并不规范：

这样应用异步代码，可能带来 JIT 优化谬误（正确的用法调用很频繁，这个谬误用法调用也很频繁，导致 JIT C2 一直优化与去优化），查看 JFR 发现这段时间也有很多 JIT 去优化：

这样可能导致平安点缺失走到 IO 一直空转期待很久的问题，须要改成正确的用法：

批改好之后，迟迟不进入 safepoint 的问题隐没。

微信搜寻“干货满满张哈希”关注公众号，加作者微信，每日一刷，轻松晋升技术，斩获各种 offer：

我会常常发一些很好的各种框架的官网社区的新闻视频材料并加上集体翻译字幕到如下地址（也包含下面的公众号），欢送关注：

  • 知乎：https://www.zhihu.com/people/…
  • B 站：https://space.bilibili.com/31…
退出移动版