最近发现一个应用，使用默认的 JFR 配置，发生了类似于雪崩的现象，这里记录下，引以为戒。

Key takeaways

1. JFR 的线程堆栈 dump 采集默认周期是everyChunk，也就是每次新建一个Chunk就会采集一次。默认每个Chunk大小为 12M，在线程比较多的时候，堆栈 dump 可能大于 12M，导致 JFR 一直切换新的 Chunk，然后又触发evenryChunk导致无限循环而雪崩。
2. 对于 JFR 默认事件采集配置（位于JDK目录/lib/jfr/default.jfc），每个采集周期和Chunk相关的，都要谨慎处理，最好周期通过固定时间写死，例如每一分钟等等，不要使用Chunk作为指标，防止上面这个问题。
3. 只有 Running 的线程才会进行 CPU 上下文切换，创建很多线程，但是同一时间有任务的线程很少（Running 线程比较少），那么线程切换也不会很频繁。等待任务的线程基本不占用 CPU 资源。

背景介绍

线上某个线程数非常多的应用，线程是空闲状态，有任务提交过来，但是过了 10s，任务才开始执行，并且这一段时间有很多类似的情况，例如：

2020-12-01 13:07:34.515  INFO [微服务名称,298ee1f359f67ff7,298ee1f359f67ff7] [19] [线程全局唯一名称：调度线程] 任务提交到线程池.....2020-12-01 13:07:43.623  INFO [微服务名称,298ee1f359f67ff7,e881ba0d86fbc4fc] [19] [线程全局唯一名称：24684780-0] 开始处理
2020-12-01 13:07:44.159  INFO [微服务名称,298ee1f359f67ff7,e881ba0d86fbc4fc] [19] [线程全局唯一名称：24684780-0] 处理完成

查看24684780-0这个线程池的统计当时的队列是空的，所有线程都是等待任务的状态。排除了有其他任务占满核心线程池导致等待的情况。

线程一直空闲，但是却不能接受任务处理，表示这个线程可能一直处于需要进入安全点SafePoint的场景。查看GC，当时的 GC 是正常的，证明并不是 GC 引起的需要进入安全点：

查看当时的 safepoint 日志（我们线上的进程开启了 safepoint 日志，参数：-Xlog:safepoint=debug:file=safepoint.log:utctime,level,tags:filecount=50,filesize=100M），发现在这期间内，有很多很多的进入 safepoint 的处理（我们只看了进入安全点（Entering safepoint region）这一行）：

[2020-12-01T13:07:32.290+0000][info ][safepoint] Entering safepoint region: ClassLoaderStatsOperation
[2020-12-01T13:07:32.335+0000][info ][safepoint] Entering safepoint region: PrintThreads
[2020-12-01T13:07:32.635+0000][info ][safepoint] Entering safepoint region: PrintJNI
[2020-12-01T13:07:32.655+0000][info ][safepoint] Entering safepoint region: FindDeadlocks
[2020-12-01T13:07:32.853+0000][info ][safepoint] Entering safepoint region: JFRCheckpoint
[2020-12-01T13:07:32.923+0000][info ][safepoint] Entering safepoint region: ClassLoaderStatsOperation
[2020-12-01T13:07:32.968+0000][info ][safepoint] Entering safepoint region: PrintThreads
[2020-12-01T13:07:33.269+0000][info ][safepoint] Entering safepoint region: PrintJNI
[2020-12-01T13:07:33.286+0000][info ][safepoint] Entering safepoint region: FindDeadlocks
[2020-12-01T13:07:33.480+0000][info ][safepoint] Entering safepoint region: ClassLoaderStatsOperation
[2020-12-01T13:07:33.524+0000][info ][safepoint] Entering safepoint region: PrintThreads
[2020-12-01T13:07:33.806+0000][info ][safepoint] Entering safepoint region: PrintJNI
[2020-12-01T13:07:33.822+0000][info ][safepoint] Entering safepoint region: FindDeadlocks
[2020-12-01T13:07:33.949+0000][info ][safepoint] Entering safepoint region: JFRCheckpoint
[2020-12-01T13:07:34.019+0000][info ][safepoint] Entering safepoint region: ClassLoaderStatsOperation
[2020-12-01T13:07:34.064+0000][info ][safepoint] Entering safepoint region: PrintThreads
[2020-12-01T13:07:34.346+0000][info ][safepoint] Entering safepoint region: PrintJNI
[2020-12-01T13:07:34.361+0000][info ][safepoint] Entering safepoint region: FindDeadlocks
[2020-12-01T13:07:34.510+0000][info ][safepoint] Entering safepoint region: ClassLoaderStatsOperation
[2020-12-01T13:07:34.555+0000][info ][safepoint] Entering safepoint region: PrintThreads
[2020-12-01T13:07:34.839+0000][info ][safepoint] Entering safepoint region: PrintJNI
[2020-12-01T13:07:34.861+0000][info ][safepoint] Entering safepoint region: FindDeadlocks
[2020-12-01T13:07:35.023+0000][info ][safepoint] Entering safepoint region: JFRCheckpoint
[2020-12-01T13:07:35.097+0000][info ][safepoint] Entering safepoint region: ClassLoaderStatsOperation
[2020-12-01T13:07:35.140+0000][info ][safepoint] Entering safepoint region: PrintThreads
[2020-12-01T13:07:35.423+0000][info ][safepoint] Entering safepoint region: PrintJNI
[2020-12-01T13:07:35.439+0000][info ][safepoint] Entering safepoint region: FindDeadlocks
[2020-12-01T13:07:35.614+0000][info ][safepoint] Entering safepoint region: ClassLoaderStatsOperation
[2020-12-01T13:07:35.654+0000][info ][safepoint] Entering safepoint region: PrintThreads
[2020-12-01T13:07:35.943+0000][info ][safepoint] Entering safepoint region: PrintJNI
[2020-12-01T13:07:35.959+0000][info ][safepoint] Entering safepoint region: FindDeadlocks
[2020-12-01T13:07:36.089+0000][info ][safepoint] Entering safepoint region: JFRCheckpoint
[2020-12-01T13:07:36.172+0000][info ][safepoint] Entering safepoint region: ClassLoaderStatsOperation
[2020-12-01T13:07:36.216+0000][info ][safepoint] Entering safepoint region: PrintThreads
[2020-12-01T13:07:36.498+0000][info ][safepoint] Entering safepoint region: PrintJNI
[2020-12-01T13:07:36.515+0000][info ][safepoint] Entering safepoint region: FindDeadlocks
[2020-12-01T13:07:36.706+0000][info ][safepoint] Entering safepoint region: ClassLoaderStatsOperation
[2020-12-01T13:07:36.749+0000][info ][safepoint] Entering safepoint region: PrintThreads
[2020-12-01T13:07:37.036+0000][info ][safepoint] Entering safepoint region: PrintJNI
[2020-12-01T13:07:37.052+0000][info ][safepoint] Entering safepoint region: FindDeadlocks
[2020-12-01T13:07:37.184+0000][info ][safepoint] Entering safepoint region: JFRCheckpoint
[2020-12-01T13:07:37.258+0000][info ][safepoint] Entering safepoint region: ClassLoaderStatsOperation
[2020-12-01T13:07:37.301+0000][info ][safepoint] Entering safepoint region: PrintThreads
[2020-12-01T13:07:37.624+0000][info ][safepoint] Entering safepoint region: PrintJNI
[2020-12-01T13:07:37.648+0000][info ][safepoint] Entering safepoint region: FindDeadlocks
[2020-12-01T13:07:37.906+0000][info ][safepoint] Entering safepoint region: ClassLoaderStatsOperation
[2020-12-01T13:07:37.955+0000][info ][safepoint] Entering safepoint region: PrintThreads
[2020-12-01T13:07:38.248+0000][info ][safepoint] Entering safepoint region: PrintJNI
[2020-12-01T13:07:38.265+0000][info ][safepoint] Entering safepoint region: FindDeadlocks
[2020-12-01T13:07:38.431+0000][info ][safepoint] Entering safepoint region: G1CollectForAllocation
[2020-12-01T13:07:38.551+0000][info ][safepoint] Entering safepoint region: JFRCheckpoint
[2020-12-01T13:07:38.620+0000][info ][safepoint] Entering safepoint region: ClassLoaderStatsOperation
[2020-12-01T13:07:38.686+0000][info ][safepoint] Entering safepoint region: PrintThreads
[2020-12-01T13:07:38.978+0000][info ][safepoint] Entering safepoint region: PrintJNI
[2020-12-01T13:07:39.001+0000][info ][safepoint] Entering safepoint region: FindDeadlocks
[2020-12-01T13:07:39.214+0000][info ][safepoint] Entering safepoint region: ClassLoaderStatsOperation
[2020-12-01T13:07:39.269+0000][info ][safepoint] Entering safepoint region: PrintThreads
[2020-12-01T13:07:39.552+0000][info ][safepoint] Entering safepoint region: PrintJNI
[2020-12-01T13:07:39.568+0000][info ][safepoint] Entering safepoint region: FindDeadlocks
[2020-12-01T13:07:39.733+0000][info ][safepoint] Entering safepoint region: JFRCheckpoint
[2020-12-01T13:07:39.813+0000][info ][safepoint] Entering safepoint region: ClassLoaderStatsOperation
[2020-12-01T13:07:39.860+0000][info ][safepoint] Entering safepoint region: PrintThreads

看上去很像 JFR 的定时采集，通过 top -Hp查看线程cpu占用：

top - 01:31:46 up 10:01,  1 user,  load average: 2.16, 2.55, 2.62
Threads: 25390 total,   2 running, 25388 sleeping,   0 stopped,   0 zombie
%Cpu(s): 17.0 us,  4.7 sy,  0.0 ni, 74.0 id,  4.1 wa,  0.0 hi,  0.2 si,  0.0 st
KiB Mem : 32120452 total,   287936 free, 20438864 used, 11393652 buff/cache
KiB Swap:        0 total,        0 free,        0 used. 11485760 avail Mem PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND
63120 root      20   0   26.8g   9.4g  22016 R 73.2 30.8 178:50.29 VM Thread
63130 root      20   0   26.8g   9.4g  22016 S 15.7 30.8  45:19.81 JFR Periodic Ta
63114 root      20   0   26.8g   9.4g  22016 S  6.6 30.8  17:31.55 GC Thread#0
63185 root      20   0   26.8g   9.4g  22016 S  6.6 30.8  44:59.01 Log4j2-TF-10-As
63346 root      20   0   26.8g   9.4g  22016 S  6.3 30.8  17:31.89 GC Thread#2
63345 root      20   0   26.8g   9.4g  22016 S  6.0 30.8  17:31.70 GC Thread#1
63347 root      20   0   26.8g   9.4g  22016 S  5.7 30.8  17:31.86 GC Thread#3
63128 root      20   0   26.8g   9.4g  22016 S  5.4 30.8  13:35.61 JFR Recorder Th
63134 root      20   0   26.8g   9.4g  22016 S  4.2 30.8  13:21.16 java
63569 root      20   0   26.8g   9.4g  22016 S  1.8 30.8  19:20.94 lettuce-epollEv
64742 root      20   0   26.8g   9.4g  22016 S  1.2 30.8   1:03.26 XNIO-2 task-6                                                                                                                                                                2777 root      20   0   26.8g   9.4g  22016 S  1.2 30.8   0:46.15 XNIO-2 task-24    。。。。。。

发现使用 CPU 最多的线程是 VM 线程，其次是 JFR 线程。怀疑是因为 JFR 采集的原因造成的所有线程一直进入安全点的问题。我们的 JFR 采集事件的配置是默认的配置，也就是 JDK 目录下的 lib 目录下的 jfr 目录下的 default.jfc 查看其中的线程 Dump 配置：

<event name="jdk.ThreadDump"><setting name="enabled" control="thread-dump-enabled">true</setting><setting name="period" control="thread-dump-interval">everyChunk</setting>
</event>

发现默认是everyChunk，也就是每次进入新的Chunk会打印一次。那么什么是Chunk?啥时候进入新的Chunk？

在 JFR 中，所有的 Event （包括通过JFR API产生的 Event 还有 JVM 产生的 EVENT），会先存储到每个线程自己的 Thread Buffer 中；在这个 Buffer 满了之后，会将 Buffer 的内容刷入 Global Buffer 中；Global Buffer 是一个环形 Buffer，保存着所有线程发送来的 Thread Buffer 中的内容。当这个环形 Buffer 存储到达上限之后，根据配置，会选择丢弃或者刷入文件，这里默认是刷入文件。这个文件，就可以理解为Chunk。

Chunk的大小是有限制的，默认是12m.但是，**这个进程的线程很多，导致线程 dump 超过了 12m。**导致 JFR 一直切换新的 Chunk，然后又触发evenryChunk导致无限循环进入安全点。

解决方案

发现问题之后，首先想到的是，减少线程数量。由于业务需要，这个业务的线程主要用来做业务隔离以及有序执行，同一时间内的 Running 线程数量并不会很多。只有 Running 的线程才会进行 CPU 上下文切换，创建很多线程，但是同一时间有任务的线程很少（Running 线程比较少），那么线程切换也不会很频繁。等待任务的线程基本不占用 CPU 资源。所以暂时先不考虑减少线程数量。

最后的解决方案是，对于 JFR 默认事件采集配置，每个采集周期和Chunk相关的，都要谨慎处理，最好周期通过固定时间写死，例如每一分钟等等，不要使用Chunk作为指标，防止出现某个采集雪崩导致不断切换chunk导致无限采集这个问题。

深度探索JFR - JFR定位线上问题实例 - JFR导致的雪崩问题定位与解决相关推荐

1. 有了这款工具，定位线上问题事半功倍｜云效工程师指北

   大家好,我叫刘玄,负责云效流水线的开发.程序员在日常工作中经常会遇到一些线上问题需要排查,本文的主人公程序员小张也不例外.但排查的过程却时常令他困扰不已.让我们一起看看他遇到了哪些问题,又是怎么解决的 ...

2. 前端录屏+定位源码，帮你快速定位线上bug

   前言 如何快速定位线上bug,是多数开发者都会遇到的难题 web-see 前端监控方案,提供了 前端录屏+定位源码 方式,让bug无处藏身 这是前端监控的第二篇,该篇讲解如何实现错误还原功能,第一篇 ...

3. 抓包神器 Wireshark，帮你快速定位线上网络故障（3）

   1  复习:TCP 三次握手&四次挥手  正式分享之前,先简单复习一下 TCP 的三次握手.四次挥手. TCP 通过三次握手建立连接(一图解千愁): TCP 协议通过四次挥手断开连接(一图知所 ...

4. Word中下一页表格无法提到上一页，导致有一大段空白的解决办法

     在用Word填写表格时,有时候会出现下一页的表格无法提到上一页,导致上一页有一大段空白的情况,如下图所示:   出现这个情况的原因是因为下一个表格设置了指定行高,而上一页剩余部分的高度不满足这个指 ...

5. 不改一行代码定位线上性能问题

   背景 最近时运不佳,几乎天天被线上问题骚扰.前几天刚解决了一个 HashSet 的并发问题,周六又来了一个性能问题. 大致的现象是: 我们提供出去的一个 OpenAPI 反应时快时慢,快的时候几十毫秒 ...

6. 不改一行代码定位线上性能问题 1

   作者:crossoverJie 来源:crossoverJie 背景 最近时运不佳,几乎天天被线上问题骚扰.前几天刚解决了一个 HashSet 的并发问题,周六又来了一个性能问题. 大致的现象是: 我 ...

7. 阿里神器 Arthas 有多强？教你一招定位线上Bug！

   今日推荐 扔掉 Postman,一个工具全部搞定,真香!为啥查询那么慢?还在直接用JWT做鉴权?JJWT真香推荐 15 款常用开发工具干掉 navicat:这款 DB 管理工具才是y(永)y(远)d( ...

8. 牛逼的不停服定位线上问题-arthas

   ​ Hello,大家好我是你们可爱的小花. 前言 你是不是为了生产环境问题,无法定位.无法中断.无法解决 项目无故异常,日志无报错.报错不够明确 测试环境无法复现.生产环境问题偶发 但重启项目后问题消 ...

9. 阿里问题定位神器 Arthas 的骚操作，定位线上BUG，超给力

   点击上方"方志朋",选择"设为星标" 回复"666"获取新整理的面试文章 作者 | likai 来源 | https://urlify.cn ...

最新文章

1. PCL：拟合平面直线和曲线以及空间曲线的原理到算法实现
2. 常用的shell脚本案例（14.04.15更新）
3. 两边同时取对数求复合函数_高中数学：对数运算三难点
4. 半夜三点，去医院看病。。。
5. python获取返回值_python 调用 shell ，获取返回值和返回信息
6. Linux基础学习一：初步认识linux
7. 小样本点云深度学习库_NeurIPS2019 | MIT与上海交大提出新型点云深度学习框架Point-Voxel CNN...
8. CGLIB动态代理模式详解
9. 摩尔庄园一直显示服务器,《摩尔庄园手游》一直显示获取远端资源号介绍 进不去怎么办...
10. SQL语句中查询数据
11. 怎样系统的学习计算机编程,如何学习电脑编程
12. 不同比例尺地形图上，典型地物的表示方法
13. 中华流传十大吉祥图解
14. Pencil：开源的GUI原型设计工具
15. ARM NEON Intrinsics示例
16. 如何使用电脑在线制作闪图？
17. 为什么GEMM是深度学习的核心
18. java word 颜色设置_通过Java设置Word页面背景色过程详解
19. 3.项目立项管理+信息系统项目管理+野马合集
20. Matlab中margin函数使用

热门文章

1. java服务端开发的好处_用java开发web的优势到底在哪里？
2. 城市中心点坐标-百度地图
3. How the Blockchain is Redefining Trust
4. LabelImg打开图片错误
5. 什么是工作流，flowable 与 Activiti对比
6. 2020 BNUZ 新生现场赛 题解
7. MySQL命令行导入含空值的orderinfo和userinfo字段内容
8. R语言输出csv文件乱码
9. 周末在厨房的一些思考
10. BUUCTF Reverse xor