性能文章>JVM 输出 GC 日志导致 JVM 卡住,我 TM 人傻了>

JVM 输出 GC 日志导致 JVM 卡住,我 TM 人傻了原创

1周前
281503

image

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

最近,我们升级了 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/428375711

JVM 统一日志配置请参考:https://zhuanlan.zhihu.com/p/111886882

在这样做之后,我们的应用出现这样一个奇怪的问题,这个问题有三种不同的现象,统一的表现是处于安全点的时间特别特别长

1.通过 safepoint 日志看出来,等待所有线程进入安全点的时间特别长(Reaching safepoint:25s多)
image
2.通过 safepoint 日志看出来,还有处于 safepoint 时间过长的,并且原因是 GC(At safepoint: 37s多)
image
查看 GC 日志,Heap before GC invocations 与输出堆结构的日志间隔了很久:
image
3.另一种处于 safepoint 时间过长的,原因也是 GC,但是间隔日志的地方不一样(29s多)
查看 GC 日志,输出堆结构的日志某些间隔了很久:
image

问题定位

首先,Java 应用线程整体处于 safepoint,这时候应用线程什么都做不了,所以依赖应用线程的监控即通过 JVM 外部监控,例如 spring actuator 暴露的 prometheus 接口,以及 Skywalking 插桩监控,是什么都看不到的,只会看到出于安全点时调用的这些方法时间特别长,但是并不是这些方法真的有瓶。

需要通过 JVM 内部线程的监控机制,例如 JVM 日志,以及 JFR(Java Flight Recording)来定位。还有就是通过 async_profiler (https://github.com/jvm-profiling-tools/async-profiler/),因为我们发现,在出问题的时候,进程本身的 CPU 占用(注意不是机器的,是这个进程的)也会激增:

image

但是非常奇怪的是,通过 async_profiler 查看 CPU 占用,发现出问题的时间段,除了:

并且在处于安全点的期间,日志也是被中断了一样,这是非常少见的,为什么这么说,请看下面分析:

针对现象一,等待所有线程进入 safepoint 时间特别长,这个一般会不断输出等待哪个线程没有进入安全点的日志,参考 JVM 源码:

https://github.com/openjdk/jdk/blob/master/src/hotspot/share/runtime/safepoint.cpp
image

但是现象一中我们并没有看到因为哪个线程导致进入 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

image

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

那么我们换成异步日志怎么样?异步日志有哪些参数呢? JVM 异步日志是 Java 17 引入的,对应的 ISSUE 是:https://bugs.openjdk.org/browse/JDK-8229517,其中的关键,在于这两个参数:
image

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

image

修改参数为异步日志,问题大幅度缓解,但是并没完全解除,进一步定位

我们修改日志为异步日志,加入启动参数: -Xlog:async,-XX:AsyncLogBufferSize=4194304。之后观察,问题得到大幅度缓解:

image

但是还是在某一个实例上出现了一次问题,查看现象,与之前的不同了,通过 safepoint 日志看,是某个线程一直 running 不愿意不进入 safepoint

image

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

image

这是一个定时刷新微服务实例列表的线程,代码对于 WebFlux 的使用并不标准:

image

这样使用异步代码,可能带来 JIT 优化错误(正确的用法调用很频繁,这个错误用法调用也很频繁,导致 JIT C2 不断优化与去优化),查看 JFR 发现这段时间也有很多 JIT 去优化:

image

这样可能导致安全点缺失走到 IO 不断空转等待很久的问题,需要改成正确的用法:

image

修改好之后,迟迟不进入 safepoint 的问题消失。

微信搜索“干货满满张哈希”关注公众号,加作者微信,每日一刷,轻松提升技术,斩获各种offer
image
我会经常发一些很好的各种框架的官方社区的新闻视频资料并加上个人翻译字幕到如下地址(也包括上面的公众号),欢迎关注:

分类:标签:
请先登录,感受更多精彩内容
快去登录吧,你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流,共同进步

为你推荐

不起眼,但是足以让你有收获的JVM内存分析案例
分析 这个问题说白了,就是说有些int[]对象不知道是哪里来的,于是我拿他的例子跑了跑,好像还真有这么回事。点该 dump 文件详情,查看相关的 int[] 数组,点该对象的“被引用对象”,发现所
从一起GC血案谈到反射原理
前言 首先回答一下提问者的问题。这主要是由于存在大量反射而产生的临时类加载器和 ASM 临时生成的类,这些类会被保留在 Metaspace,一旦 Metaspace 即将满的时候,就会触发 Fu
关于内存溢出,咱再聊点有意思的?
概述 上篇文章讲了JVM在GC上的一个设计缺陷,揪出一个导致GC慢慢变长的JVM设计缺陷,可能有不少人还是没怎么看明白的,今天准备讲的大家应该都很容易看明白 本文其实很犹豫写不写,因为感觉没有
协助美团kafka团队定位到的一个JVM Crash问题
概述 有挺长一段时间没写技术文章了,正好这两天美团kafka团队有位小伙伴加了我微信,然后咨询了一个JVM crash的问题,大家对crash的问题都比较无奈,因为没有现场,信息量不多,碰到这类问题我
又发现一个导致JVM物理内存消耗大的Bug(已提交Patch)
概述 最近我们公司在帮一个客户查一个JVM的问题(JDK1.8.0_191-b12),发现一个系统老是被OS Kill掉,是内存泄露导致的。在查的过程中,阴差阳错地发现了JVM另外的一个Bug。这个B
JVM实战:优化我的IDEA GC
IDEA是个好东西,可以说是地球上最好的Java开发工具,但是偶尔也会卡顿,仔细想想IDEA也是Java开发的,会不会和GC有关,于是就有了接下来对IDEA的GC进行调优 IDEA默认JVM参数: -
不起眼,但是足以让你收获的JVM内存案例
今天的这个案例我觉得应该会让你涨姿势吧,不管你对JVM有多熟悉,看到这篇文章,应该还是会有点小惊讶的,不过我觉得这个案例我分享出来,是想表达不管多么奇怪的现象请一定要追究下去,会让你慢慢变得强大起来,
如何通过反射获得方法的真实参数名(以及扩展研究)
前段时间,在做一个小的工程时,遇到了需要通过反射获得方法真实参数名的场景,在这里我遇到了一些小小的问题,后来在部门老大的指导下,我解决了这个问题。通过解决这个问题,附带着我了解到了很多新的知识,我觉得