堆内存持续占用高且 ygc回收效果不佳” 排查处理实践

浅浅的花香味﹌ 2023-09-24 21:39 15阅读 0赞

#### 说明：部分素材来源于网络，数据分析全为真实数据。 ####

#### 一、 问题背景 ####

自建的两套工具，运行一段时间后均出现 内存占用高触发报警，频繁young gc且效果不佳。曾经尝试多次解决，因各种原因耽搁，最近下定决心处理此问题。

#### 二、 问题描述 ####

Q：堆内存1018M，使用达到950M左右触发一次young gc，ygc之后内存占用630M，未发生full gc

![format_png][]

#### 三、 容器配置 ####

已处理关键信息

•主机名 xxx

•实例ID xxx

•ip

•操作系统名称Linux

•操作系统体系结构amd64

•CPU个数2

•JRE版本1.8.0\_191

•JVM启动时间2023-02-18 17:14:10.873

•启动路径/export/App

•Full GCPS MarkSweep

•Young GCPS Scavenge

•进程ID115135

•物理内存大小251.4GB(269888389120Byte)

•交换区大小0.0GB(0Byte)

•虚拟内存大小12.5GB(13368197120Byte)

•应用路径/export/App/lib/tp-center-web.jar!/BOOT-INF/lib/

•JVM启动参数-javaagent:/export/xxx/lib/pfinder-profiler-agent-1.0.8-20210322032622-6f12bda2.jar -Ddeploy.app.name=xxx -Ddeploy.app.id=xxx -Ddeploy.instance.id=0 -Ddeploy.instance.name=server1 -DJDOS\_DATACENTER=HT -Dloader.path=./conf -Dspring.profiles.active=pre -Xms1024m -Xmx1024m -Xmn384m -XX:MetaspaceSize=64m -XX:CMSInitiatingOccupancyFraction=70 -XX:+UseCMSInitiatingOccupancyOnly -XX:ParallelGCThreads=2 -XX:CICompilerCount=2 -XX:MaxDirectMemorySize=128m -Duser.timezone=Asia/Shanghai -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=xxx -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false -Djava.rmi.server.hostname=xxx

#### 四、 问题分析 ####

##### 1、 young gc的时机？ #####

R：ygc在新生代的eden区满了之后就会触发，采用复制算法回收新生代的垃圾。

##### 2、 为何young gc后堆内存使用率仍然很高？ #####

R：新生代过小，大对象直接进入老年代，编码时要尽量减少大对象的使用。

##### 3、 full gc 的时机？ #####

R：HotSpot VM里，除了CMS之外，其它能收集老年代的GC都会同时收集整个GC堆，包括新生代

1） 发生fgc之前进行检查，如果 老年代可用的连续内存空间 < 新生代历次ygc后升入老年代的对象总和的平均大小，此时先触发old gc，然后执行ygc

2） 执行ygc之后有一批对象需要放入老年代，此时老年代没有足够空间存放对象，必须触发一次ogc

3） 老年代内存使用率超过阈值，也要触发ogc

4） 元空间不足时也会触发一次

##### 4、 什么原因导致内存占用高？ #####

R：heap dump分析、gc日志

#### 五、 回收器 ####

•吞吐量优先（Parallel Scavenge）：新生代收集器，侧重于吞吐量（吞吐量=运行用户代码时间/(运行用户代码时间+运行垃圾收集时间)）的控制。

•Serial Old：Serial Old是Serial收集器的老年代版本， 它同样是一个**单线程收集器**， 使用标记-整理算法：由于老年代 Serial Old 收集器在服务端应用性能上的“拖累”, 使用Parallel Scavenge 收集器也未必能在整体上获得吞吐量最大化的效果。由于单线程的老年代收集中**无法充分利用服务器**多处理器的并行处理能力, 在老年代内存空间很大而且硬件规格比较高级的运行环境中, 这种组合的**总吞吐量甚至不一定比ParNew加CMS的组合来得优秀。**

•Parallel Old ：是 Parallel Scavenge 收集器的老年代版本, 支持多线程并发收集, 基于**标记-整理算法**实现. 这个收集器是直到 JDK 6 时才开始提供的, 在此之前, 新生代的 Parallel Scavenge收集器一直处于相当尴尬的状态, 原因是如果新生代选择了 Parallel Scavenge 收集器, 老年代除了 Serial Old(PS MarkSweep)收集器以外别无选择

**UseParallelGC: JDK9 之前虚拟机运行在 Server 模式下的默认值, 使用 ParallelScavenge + Serial Old(PS MarkSweep)的收集器组合进行内存回收。**

UseParallelOldGC: 打开此开关后, 使用 Parallel Scavenge + Parallel Old 的收集器组合进行内存回收。

•ParNew收集器与Parallel收集器类似：此收集器是许多运行在Server模式下的虚拟机的首选，除了Serial收集器外，只有它能与CMS收集器配合工作

•并发标记清除（CMS）回收器：是一种以获取最短回收停顿时间为目标的回收器，该回收器是基于“标记-清除”算法实现的。注重回收时产生的停顿时间，是停顿时间最短的收集器。非常适合注重用户体验的应用上，是Hotspot虚拟机第一款真正意义上的并发收集器，第一次***实现了让垃圾收集线程与用户线程几乎同时运行***

![format_png 1][]

#### 六、 优化策略 ####

##### 1、 加gc日志 #####

\-XX:+PrintGCDetails // 创建详细的gc日志

\-XX:+PrintGCTimeStamps

\-Xloggc:/export/Logs/com/gc.log // gc日志文件名

\-XX:+UseGCLogFileRotation // 限制保存在gc日志中的数据量

\-XX:GCLogFileSize=10M // 日志文件大小

\-XX:NumberOfGCLogFiles=10 // 日志文件个数

\-XX:+HeapDumpAfterFullGC // fullgc前dump文件保存

\-XX:HeapDumpPath=/export/Logs/com/fgcdump.log // dump文件保存路径

\-XX:+HeapDumpOnOutOfMemoryError

\-XX:HeapDumpPath=目录 // oom时生成dump文件

// ================================= 附加参数如下 =============================================

// 可以使用-XX:DisableExplicitGC选项禁用显示调用Full gc（system.gc在cms gc下我们通过-XX:+ExplicitGCInvokesConcurrent来做一次稍微高效点的GC(效果比Full GC要好些)）

\-XX:+UnlockExperimentalVMOptions // 解锁实验参数，允许使用实验性参数，JVM中有些参数不能通过-XX直接复制需要先解锁，比如要使用某些参数的时候，可能不会生效，需要设置这个参数来解锁 -XX:+UseParNewGC // 真正的并发收集器，与CMS搭配使用（ParNew收集器是Serial收集器的多线程版本，使用这个参数后会在新生代进行并行回收，老年代仍旧使用串行回收。新生代S区任然使用复制算法） -XX:+UseConcMarkSweepGC // 和应用程序线程一起执行，相对于Stop The World来说虚拟机停顿时间较少。停顿减少，吞吐量会降低。它使用的是 标记清除算法，运作过程为四个步骤，分别是 初始标记—并发标识—重新标记—并发清除。它是老年代的收集算法，新生代使用ParNew收集算法。默认关闭

**CMS收集器的缺点是对服务器CPU资源较为敏感，在并发标记时会降低吞吐量。它使用的标记清除算法也会产生大量空间碎片，空间碎片的存在会加大Full GC的频率，虽然老年代还有足够的内存，但是因为内存空间不连续，不得不进行Full GC** \-XX:CMSInitiatingOccupancyFraction=75 // 允许最大占用占用率 -XX:+UseCMSInitiatingOccupancyOnly // 只用设定的回收阈值,如果不指定,JVM仅在第一次使用设定值,后续则自动调整 -XX:+ExplicitGCInvokesConcurrent // ExplicitGCInvokesConcurrent这个参数是配合CMS使用的，开启后System.gc()还是会触发Full GC，不过并不是一个完全的stop-the-world的Full GC，而是并发的CMS GC -XX:+ParallelRefProcEnabled // 可以用来并行处理 Reference，以加快处理速度，缩短耗时 -XX:+CMSParallelRemarkEnabled // 在CMS GC前启动一次ygc，目的在于减少old gen对ygc gen的引用，降低remark时的开销-----一般CMS的GC耗时 80%都在remark阶段

// **切记以下参数不要乱加**

\-XX:+UseCMSCompactAtFullCollection // Full GC后，进行一次整理，整理过程是独占的，会引起停顿时间变长。仅在使用CMS收集器时生效。

**-XX:CMSFullGCsBeforeCompaction** // 默认为 0，就是每次FullGC都对老年代进行碎片整理压缩，建议保持默认

##### 2、 gc日志指标 #####

S0: 新生代中Survivor space 0区已使用空间的百分比

S1: 新生代中Survivor space 1区已使用空间的百分比 E: 新生代已使用空间的百分比 O: 老年代已使用空间的百分比 M: 元空间已使用空间的百分比

CCS: 压缩类空间利用率百分比 YGC: 从应用程序启动到当前，发生Yang GC 的次数

YGCT: 从应用程序启动到当前，Yang GC所用的时间【单位秒】 FGC: 从应用程序启动到当前，发生Full GC的次数 FGCT: 从应用程序启动到当前，Full GC所用的时间 GCT: 从应用程序启动到当前，用于垃圾回收的总时间【单位秒】

##### 3、 最大线程数 #####

系统可创建最大线程数 = （机器本身可用内存 - JVM分配的堆内存 - JVM元数据区）/ 线程栈大小

##### 4、 内存分析 #####

###### 4.1 常用命令 ######

**4.1.1 jstack**

// Java堆栈跟踪工具，它用于打印出给定的java进程ID、core file、远程调试服务的Java堆栈信息.

jstack命令用于生成虚拟机当前时刻的线程快照线程快照是当前虚拟机内每一条线程正在执行的方法堆栈的集合，使用其主要目的是定位线程出现长时间停顿的原因，如线程间死锁、死循环、请求外部资源导致长时间等待等问题线程出现停顿的时候通过jstack来查看线程的调用堆栈，就可以知道没有响应的线程到底在做什么事，或者等待什么资源若java程序崩溃生成core文件，jstack可用来获得core文件的java stack和native stack的信息

还可附属到正在运行的java程序上，看到当前运行的java程序的java stack和native stack信息，若呈现hung状态，jstack很有用

应用：jstack \[option\] // 打印某个进程的堆栈信息

•线程状态

![format_png 2][]

•Monitor监视锁

![format_png 3][]

**item1：实战案例1 jstack分析死锁问题**

死锁指的是两个或两个以上的线程在执行过程中，因**争夺资源而造成的一种互相等待**的现象，若无外力作用，将无法继续进行

**jps：终端中输入jsp查看当前运行的java程序**

8896

5684 JUnitStarter

17836 Jps

19804 Launcher

**文件分析：【本文件未死锁，仅用于分析，死锁时会出现 线程1持有A等B，线程2持有B等A】**

"consumer\_monitor\_report\_tp\_pre\_1\_1\_3\_1677132947525" \#7851 daemon prio=5 os\_prio=0 tid=0x00007f8d2001b000 nid=0x31c8c waiting on condition \[0x00007f8ceeeef000\] java.lang.Thread.State: TIMED\_WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000000fad6df60> (a java.util.concurrent.CountDownLatch$Sync) ... Locked ownable synchronizers: - None

// consumer\_monitor\_report\_tp\_pre\_1\_1\_3\_1677132947525 的线程处于TIMED\_WAITING状态，持有 - None 锁（无锁），等待 0x00000000fad6df60 的锁

**item2：实战案例2 jstack分析cp过高问题**

•通过 top 命令查看各个进程cpu使用情况，默认按cpu使用率高到低排序

•通过 top -Hp pid 查看该进程下，各个线程的cpu使用情况

•**定位到cpu占用率高的线程**之后，使用 jstack pid 命令查看当前java进程的堆栈状态

•nid=0x31c8b 进制转换，文件中，每个线程都有一个nid，查看状态

**4.1.2 jstat**

// java虚拟机统计信息工具，利用JVM内建的指令对Java应用程序的资源和性能进行实时的命令行的监控

远程监控：jstat -gcutil port@ip

说明：GCT = YGCT + FGCT

**4.1.3 jmap-histo**

// 查看堆内存中的对象数目、大小统计直方图，如果带上live则只统计活对象

包括对 Heap size 和 垃圾回收状况的监控

num \#instances \#bytes class name ---------------------------------------------- 1: 3153872 297505208 \[C 2: 214428 113791808 \[B 3: 88856 81288672 \[I 4: 3123084 74954016 java.lang.String 5: 520601 20824040 java.util.LinkedHashMapEntry6:26877915051624java.util.zip.Deflater7:10598114981000\[Ljava.lang.Object;8:3888349332016java.util.zip.ZStreamRef9:12247197248\[J10:179735855104\[Ljava.util.HashMapEntry 6: 268779 15051624 java.util.zip.Deflater 7: 105981 14981000 \[Ljava.lang.Object; 8: 388834 9332016 java.util.zip.ZStreamRef 9: 1224 7197248 \[J 10: 17973 5855104 \[Ljava.util.HashMapEntry6:26877915051624java.util.zip.Deflater7:10598114981000\[Ljava.lang.Object;8:3888349332016java.util.zip.ZStreamRef9:12247197248\[J10:179735855104\[Ljava.util.HashMapNode; 11: 177935 5693920 java.util.HashMapNode12:1696785429696org.elasticsearch.common.bytes.BytesArray13:1109005323200java.util.zip.Inflater14:543144779632java.lang.reflect.Method15:423363725568org.elasticsearch.search.SearchHit16:1271123050688org.elasticsearch.common.text.Text17:833582667456java.util.concurrent.ConcurrentHashMapNode 12: 169678 5429696 org.elasticsearch.common.bytes.BytesArray 13: 110900 5323200 java.util.zip.Inflater 14: 54314 4779632 java.lang.reflect.Method 15: 42336 3725568 org.elasticsearch.search.SearchHit 16: 127112 3050688 org.elasticsearch.common.text.Text 17: 83358 2667456 java.util.concurrent.ConcurrentHashMapNode12:1696785429696org.elasticsearch.common.bytes.BytesArray13:1109005323200java.util.zip.Inflater14:543144779632java.lang.reflect.Method15:423363725568org.elasticsearch.search.SearchHit16:1271123050688org.elasticsearch.common.text.Text17:833582667456java.util.concurrent.ConcurrentHashMapNode 18: 21894 2416424 java.lang.Class 19: 42925 2060400 java.util.HashMap 20: 55340 1770880 [java.io][].ObjectStreamClass$WeakClassKey

**4.1.4 jmqp-heap**

// 查看进程堆内存使用情况，包括使用的GC算法、堆配置参数和各代中堆内存使用情况

using thread-local object allocation. Parallel GC with 2 thread(s)

Heap Configuration: MinHeapFreeRatio = 0 MaxHeapFreeRatio = 100 MaxHeapSize = 1073741824 (1024.0MB) NewSize = 402653184 (384.0MB) MaxNewSize = 402653184 (384.0MB) OldSize = 671088640 (640.0MB) NewRatio = 2 SurvivorRatio = 8 MetaspaceSize = 67108864 (64.0MB) CompressedClassSpaceSize = 1073741824 (1024.0MB) MaxMetaspaceSize = 17592186044415 MB G1HeapRegionSize = 0 (0.0MB)

Heap Usage: PS Young Generation Eden Space: capacity = 393216000 (375.0MB) used = 381729360 (364.0454864501953MB) free = 11486640 (10.954513549804688MB) 97.07879638671875% used From Space: capacity = 4718592 (4.5MB) used = 3489328 (3.3276824951171875MB) free = 1229264 (1.1723175048828125MB) 73.94849989149306% used To Space: capacity = 4718592 (4.5MB) used = 0 (0.0MB) free = 4718592 (4.5MB) 0.0% used PS Old Generation capacity = 671088640 (640.0MB) used = 633681304 (604.3255844116211MB) free = 37407336 (35.674415588378906MB) 94.4258725643158% used

49351 interned Strings occupying 4857128 bytes.

**4.1.5 jmqp-dump**

// 生成堆快照（**瞬时**）

利用jvisualvm分析内存dump文件：点击文件->装入->文件类型选“堆”

![format_png 4][]

**Visual VM的OQL语言**是对HeapDump进行查询，类似于SQL的查询语言，它的基本语法如下：

select \[ from \[instanceof\] \[ where \] \]

OQL由3个部分组成：select子句、from子句和where子句。select子句指定查询结果要显示的内容。from子句指定查询范围，可指定类名，如java.lang.String、char\[\]、\[[Ljava.io][].File;（File数组）。where子句用于指定查询条件。

![format_png 5][]

![format_png 6][]

![format_png 7][]

###### 4.2 加日志后 ######

**见调优方案**

#### 七、 调优方案1：增大新生代 ####

![format_png 8][]

![format_png 9][]

##### 1、 解析gc日志 #####

**元空间分配64M（不足自动调整了），新生代改为480m**

•25.939: \[Full GC (Metadata GC Threshold) \[PSYoungGen: 4133K->0K(461312K)\] \[ParOldGen: 34773K->36327K(557056K)\] 38907K->36327K(1018368K), \[Metaspace: 62967K->62967K(1105920K)\], 0.3564880 secs\] \[Times: user=0.72 sys=0.02, real=0.36 secs\]

<table style=""> 
 <tbody> 
 <tr> 
 <td style="width:61px;vertical-align:top;height:51px;">25.939</td> 
 <td style="width:61px;vertical-align:top;height:51px;">Full GC (Metadata GC Threshold)</td> 
 <td style="width:61px;vertical-align:top;height:51px;">GC (Allocation Failure)</td> 
 <td style="width:61px;vertical-align:top;height:51px;">GC (GCLocker Initiated GC)</td> 
 <td style="width:61px;vertical-align:top;height:51px;">PSYoungGen: 4133K-&gt;0K(461312K)</td> 
 <td style="width:61px;vertical-align:top;height:51px;">ParOldGen: 34773K-&gt;36327K(557056K)</td> 
 <td style="width:61px;vertical-align:top;height:51px;">38907K-&gt;36327K(1018368K)</td> 
 <td style="width:61px;vertical-align:top;height:51px;">Metaspace: 62967K-&gt;62967K(1105920K)</td> 
 <td style="width:61px;vertical-align:top;height:51px;">0.3564880 secs</td> 
 <td style="width:61px;vertical-align:top;height:51px;">user=0.72</td> 
 <td style="width:61px;vertical-align:top;height:51px;">sys=0.02</td> 
 <td style="width:61px;vertical-align:top;height:51px;">real=0.36 secs</td> 
 </tr> 
 <tr> 
 <td style="width:61px;vertical-align:top;height:51px;">容器已启动时间</td> 
 <td style="width:61px;vertical-align:top;height:51px;">发生一次 fgc（元空间不够用导致）</td> 
 <td style="width:61px;vertical-align:top;height:51px;">年轻代无足够空间</td> 
 <td style="width:61px;vertical-align:top;height:51px;">openJDK的一个bug，只是一直没被修复（<a style="color:#0A6CFF;" href="https://link.juejin.cn?target=https%3A%2F%2Fbugs.openjdk.org%2Fbrowse%2FJDK-8048556%25EF%25BC%2589%25EF%25BC%258C%25E4%25B8%258D%25E7%2594%25A8%25E8%25BF%2587%25E4%25BA%258E%25E5%2585%25B3%25E6%25B3%25A8" rel="nofollow">bugs.openjdk.org/browse/JDK-…</a></td> 
 <td style="width:61px;vertical-align:top;height:51px;">默认总容量为 0.9*新生代</td> 
 <td style="width:61px;vertical-align:top;height:51px;">数据变大因为新生代的垃圾进来了</td> 
 <td style="width:61px;vertical-align:top;height:51px;">GC前堆内存已使用容量→GC堆内存容量（堆内存总容量 = 0.9*新生代 + 老年代）</td> 
 <td style="width:61px;vertical-align:top;height:51px;">元空间未回收</td> 
 <td style="width:61px;vertical-align:top;height:51px;">整个GC花费时间</td> 
 <td style="width:61px;vertical-align:top;height:51px;">CPU工作在用户态时间</td> 
 <td style="width:61px;vertical-align:top;height:51px;">CPU工作在内核态时间</td> 
 <td style="width:61px;vertical-align:top;height:51px;">GC总时间</td> 
 </tr> 
 </tbody> 
</table>

#### 八、 调优方案2：增大元空间 + CMS & PNEW ####

**以下方案暂时没啥问题**

![format_png 10][]

#### 九、 临时方案以观后效 ####

说明：去批量处理，降低对象大小，也许也是一个不错的方案，待验证。

\-Xms1024m -Xmx1024m -Xmn480m -Xss512k -XX:MetaspaceSize=128m -XX:ParallelGCThreads=2 -XX:CICompilerCount=2 -XX:MaxDirectMemorySize=256m -XX:+UnlockExperimentalVMOptions -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=75 -XX:+UseCMSInitiatingOccupancyOnly -XX:+ExplicitGCInvokesConcurrent -XX:+ParallelRefProcEnabled -XX:+CMSParallelRemarkEnabled -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:/export/Logs/xxx/gc.log -XX:GCLogFileSize=100M -XX:+HeapDumpAfterFullGC -XX:HeapDumpPath=/export/Logs/xxx/fgcdump.log

部署稳定后jvm监控图表如下：

![format_png 11][]

作者：京东云开发者

链接：[https://juejin.cn/post/7205217123663527994][https_juejin.cn_post_7205217123663527994]

[format_png]: https://img-blog.csdnimg.cn/img_convert/4b7e33f92ff2d5a0603b680442958612.webp?x-oss-process=image/format,png
[format_png 1]: https://img-blog.csdnimg.cn/img_convert/48f9a1ee23ee2368512044407f0851f1.webp?x-oss-process=image/format,png
[format_png 2]: https://img-blog.csdnimg.cn/img_convert/4c9238e1eb19a25656de00a8f7a320af.webp?x-oss-process=image/format,png
[format_png 3]: https://img-blog.csdnimg.cn/img_convert/a709b0b814fb4c91023b45412a2cd4dd.webp?x-oss-process=image/format,png
[java.io]: https://link.juejin.cn?target=http%3A%2F%2Fjava.io%2F
[format_png 4]: https://img-blog.csdnimg.cn/img_convert/1fbef0ecfd0bc843da92d478442b1eb1.webp?x-oss-process=image/format,png
[Ljava.io]: https://link.juejin.cn?target=http%3A%2F%2Fljava.io%2F
[format_png 5]: https://img-blog.csdnimg.cn/img_convert/c4a813725fc5a763015ec6d66d772445.webp?x-oss-process=image/format,png
[format_png 6]: https://img-blog.csdnimg.cn/img_convert/5428486eadffa2a353601ce01cb298c7.webp?x-oss-process=image/format,png
[format_png 7]: https://img-blog.csdnimg.cn/img_convert/063e5f90b0bc799380eaf82d1f59298e.webp?x-oss-process=image/format,png
[format_png 8]: https://img-blog.csdnimg.cn/img_convert/6f31718ab4581d6d4970b26998eac74e.webp?x-oss-process=image/format,png
[format_png 9]: https://img-blog.csdnimg.cn/img_convert/5887c3c93d92f5be145a8c9b2777f2c2.webp?x-oss-process=image/format,png
[format_png 10]: https://img-blog.csdnimg.cn/img_convert/fd3925c7ef19a78c2936eb503e0062f7.webp?x-oss-process=image/format,png
[format_png 11]: https://img-blog.csdnimg.cn/img_convert/3bd4882b22d3e08ac0bd5194721533e6.webp?x-oss-process=image/format,png
[https_juejin.cn_post_7205217123663527994]: https://juejin.cn/post/7205217123663527994