《深入理解Java虚拟机》(五) JVM调优案例

问题

我们公司的程序是的B/S架构，工作中碰到客户提出一个问题，他们的系统最近突然会用着用着就卡死掉--浏览器访问服务器一开始会卡顿，直至最终会完全卡死没有响应。
并且客户反馈的是最近才变卡的，之前一直没有问题，现在一旦系统卡住就需要重启，对正常使用造成了严重影响。
客户的服务器配置如下(应用程序服务器以及数据库服务器都是如下配置)

内存：32G
磁盘：机械 2 T
CPT: 两颗4核 CPU

由于我司产品是客户内部部门间使用，所以并发量并不大，上述配置已经完全足够开销。

排查问题经过了如下的过程：

排除是否数据库卡顿造成

一开始虽然就可以确定不是数据库问题(因为不是一直卡顿，而是某段时间间歇性卡顿)，还是看了一下Oracle的 awr 报告，得到的结论也确实不是数据库问题。

任务管理器

简单粗暴的直接看任务管理器，这次发现了问题的端倪了，每次系统卡死前，程序服务器的内存、CPU的占用率都接近拉满，而数据库服务器则没有什么变化。

与客户沟通

经过再次与客户沟通，得知最近一段时间，他们大量的部门在使用系统中一个通过excel导入数据的功能。（该功能通过使用HSSFWorkbook达到批量从excel中导入数据），基本上可以确定问题跟使用HSSFWorkbook息息相关。结合内存几乎耗尽，程序无响应的问题，那么极有可能是Full GC时间太久导致了卡顿。（如果收集器的GC 线程与用户程序线程串行，当进行GC 时必须停掉所有用户线程，当堆很大的时候就会导致GC时间过久。）

至此开始通过JVM排查问题：

首先要得到JVM日志，我们在客户服务器的tomcat的bin/catalina.bat中添加了如下参数：

	set "JAVA_OPTS=-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=D:\DUMP_FILES\"
	set "JAVA_OPTS=%JAVA_OPTS% -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -Xloggc:D:\\gc.log"

在这里插入图片描述

JVM参数介绍

-XX:+HeapDumpOnOutOfMemoryError   //当堆内存溢出自动打印dump日志
-XX:HeapDumpPath=D:\DUMP_FILES\   //dump日志路径

-verbose:gc                                               // 开启GC 日志功能
-XX:+PrintGCDetails                                 // 打印详细GC信息 
-XX:+PrintGCDateStamps                        // GC 日志打印时间戳
-XX:+PrintHeapAtGC                                //Full GC 前后打印 堆的总览信息
-Xloggc:D:\\gc.log                                     //GC 日志路径

完事具备，让客服重启服务器，然后等待凶手浮出水面，来一个守株待兔。

客户服务器卡死，没有dump日志，但是GC日志 gc.log 已经有内容了，其中部分内容如下截图：

第一次Full GC

老年代一切正常GC 后占用变小，Full GC实际时间0.08秒正常，截图如下：

在这里插入图片描述

第二次Full GC截图

发现了问题，实际耗时0.22秒，总的来说正常；需要关注的是，GC 后老年代总空间变大了，并且占用率也变大；(大量对象进入了老年代)

在这里插入图片描述

第三次Full GC 截图

Full GC 实际耗时 0.17秒，正常。回收后老年代从52%变成了16%，正常。

在这里插入图片描述

分析前三次Full GC：
GC耗时正常，唯一不正常的是三次Full GC间隔时间较短，对比观察第一次Full GC之后和第三次Full GC之后：发现，老年代和新生代总空间大小都发生了变化，这时可以推测这是JVM在自动调整内存。

直至开始出现异常的Full GC

后续几次Full GC 正常，直到第5次Full GC，这次Full GC实际耗时0.59秒，开始异常。
在这里插入图片描述
此时时间已经来到了下午15点，对比上午11：30左右发生的Full GC，此时老年代和新生代内存再一次变大了，此次Full GC eden变化不大回收了60M左右空间。

Full GC 后老年代空间再次变大，此时大致可以推论用户操作高峰期到来，大量对象开始向老年代进军。

如下是第6次Full GC，这次Full GC实际耗时1.94秒，异常它来了。

在这里插入图片描述
第六次 Full GC 后

	eden    约 200 M左右
	from space     约 300M
	to space         约 300M

	Old  约  1 G左右

Full GC耗时1.94秒，这已经不正常了，同时发现此次Full GC后老年代不减反增；再看Full GC发生时间：紧邻第五次Full GC，可知此时收集速度已经慢于内存分配速度，需要触发Full GC 得到足够内存空间进行内存分配。

继续分析：

第七次Full GC到来

相距第六次Full GC时间只过去了16秒，此次Full GC实际耗时2.25秒，此时Full GC开始高频率发生，且造成时间停顿较久：已经达到秒级，可以预见客户说的系统卡死就在即将到来。
在这里插入图片描述

最终程序卡死时的Full GC

第69~第71次Full GC，时间间隔极短，且耗时极长（3 ~ 4 秒），此时系统已经卡死，此时老年代占用率已经99%，已经没有空间可以给对象分配内存。
在这里插入图片描述

分析

此时用户服务器的32 G内存已经占用了99%，并且已经没有什么回收的余地了。虽然此时老年代和新生代占用内存总和也不超过10个G，那么剩下的20多个G内粗去哪里了呢?为什么内存占用了99%呢，估计是因为HSSFWorkbook 操作 Excel 时占用了堆外内存(没深究这个，有懂行的小伙伴望不吝赐教)。

可以得到的结论是，当对象分配速度过快，GC收集的速度已经跟不上内存分配的速度，老年代很快被占满，这样就会导致频繁的Full GC；另外由于Java堆不断自行拓展占用内存大小，最后造成堆占用空间越来越大，而堆越大导致Full GC时间越来越久，如此形成恶性循环停顿时间越来越长；直至最终，服务器内存被占满，Full GC无法回收内存空间，程序卡死。

结合分析，那么需要做的就是事情大致围绕两个核心：

选择并发方式的 GC 收集器(CMS 、G1)，减少STW操作(Stop The Word);
JVM调优，尽量避免发生Full GC;

处理方法

拟处理方案如下：

1.服务器扩大内存为64G 32核

客户财大气粗不愁资源

2.修改JVM默认的垃圾收集器(Parallel GC)，改为G1 或者 CMS。

如果选用G1收集器，参数设置如下

		#开启G1
		-XX:+UseG1GC 
		
		#指定堆大小最大为6个G
		-Xmx6144m 
		
		# 设置region大小2的24次方（16M） 可选范围：1M ~ 32 M		
		-XX:G1HeapRegionSize=16777216
		
		# STW （stop the word） 工作线程数  STW_Thread_num =  num_of_cup > 8 ?  5/num_of_cup  :  num_of_cup;   (三目运算符不解释)
		-XX:ParallelGCThreads=20   ###客户服务器CPU逻辑处理器数：32 * 5 / 8 = 20
		
		# 设置并行标记的线程数 : num of STW_Thread_num / 4  
		-XX:ConcGCThreads=5   #####   20/4 = 5  
		
		#  触发标记周期的堆占用率阈值：当达到80% 时触发一次Mixed GC
		-XX:InitiatingHeapOccupancyPercent=60

假如选用CMS 收集器，参数如下：

		# 启用  CMS
		-XX:+UseConcMarkSweepGC
		
		# 指定堆大小最大为6个G
		-Xmx6144m 
		
		# 指定 新生代和老年代大小比例 1：2  CMS可以使用，但是G1 不适用
		# 如果G1 中指定新生代和老年代比例，会对G1的时间停顿模型产生破坏
		-XX:NewRatio=2
		
		# 年轻代为并行收集
		-XX:+UseParNewGC

		#  降低标记停顿
		-XX:+CMSParallelRemarkEnabled

3. 针对CMS 收集器

由于大量的HSSFWorkbook对象进入了老年代，那么肯定带来了大量的跨代引用(新生代对象和老年代对象之间的相互引用)，那么此时需要如下指令，强制每次清理前，先进行一次新生代的收集，那么在标记阶段的STW操作耗时必将大大改善。

	# 注意，只能CMS 收集器使用
	-XX:+ScavengeBeforeFullGC
	-XX:+CMSScavengeBeforeRemark

4. 结合GC 日志，我们还可以延长对象在eden驻留时间，减小老年代压力

 		#  通用指令 CMS 和 G1 都可使用
 		-XX:MaxTenuringThreshold=15

处理原因

或许有人就要问了，为什么要改垃圾收集器，只加内存不行么？

Parallel 收集器，用户线程与GC线程串行，收集时用户线程必须停下，当老年代不断膨胀，那么收集的时间不断变长就造成了恶果。

最终我们选择了G1 收集器。

了解G1的小伙伴应该知道，G1收集的步骤是：

graph LR A( 初始标记 ) B( 并发标记 ) C( 最终标记 ) D( 筛选回收 ) A -->B -->C-->D

其中耗时的操作都是并发进行的，并不会停掉用户线程；众所周知，G1 收集器追寻的是程序的最小停顿，所以用在此处挺好。至于G1会占用JVM 10~20%的内存，那么为什么不用CMS收集，因为客户有钱啊(滑稽)，后续客户把程序服务器配置加到了64G 32核心。小伙伴碰到类似问题可以试试 CMS 是否也有奇效。

最终，换成G1收集器后，用户程序逐渐正常，得到了如下GC 日志：
G1 堆内存约 1G 毫无压力，可以关注截图，最后一行的Time: user 主要与服务器CPU收集相关暂不关注，主要看的是，real = 0.05 secs ，0.05 秒：这个才是咱要看到的效果。

在这里插入图片描述
G1 堆内存2G+,依旧无压力，real = 0.03 secs

在这里插入图片描述

最终

后续从GC 日志里也没发现别的异常，问题基本解决。G1收集器的日志里没发现Full GC记录(在G1垃圾收集器中，最好的优化状态就是通过不断调整分区空间，避免进行full gc，可以大幅减少延时)，并且G1堆内存峰值也就在2G左右，那么可以得到的结论是：或许不用拓展硬件，G1收集器再适当调优就能解决该问题。

写在 2023-10-14

不知不觉中两年多过去，再回过头来反刍的时候，还是发现了曾经的不成熟；

其实文中分析的原因都对，就是大量导入 excel 导致分配内存过快，并且如果文件较大、客户端并发较高时，很容易就内存溢出了，毕竟 HSSFWorkbook 读取 excel 是要读取文件到内存中的。

如果了解 NIO 的话，就知道前文提到的 20G 内存去哪了，答案就是 <直接内存> 它不受堆管辖。

文中提到的解决之道其实也尚可，加大内存、使用G1 可以解决燃眉之急，但是治标不治本，随着并发量持续上升，同样有耗尽的时候。

正确的姿势应当是，优化 HSSFWorkbook 读取excel的部分，应当使用 CSV 支持按行读取，而非全部载入内存 <直接内存>，这样可能读取效率变低了，但是起码可以最有效的避免内存溢出。

posted @ 2021-06-19 15:19 bokerr 阅读(208) 评论(1) 编辑收藏举报

刷新页面返回顶部

bokerr

《深入理解Java虚拟机》(五) JVM调优案例

问题

排查问题经过了如下的过程：

排除是否数据库卡顿造成

任务管理器

与客户沟通

至此开始通过JVM排查问题：

JVM参数介绍

第一次Full GC

第二次Full GC截图

第三次Full GC 截图

直至开始出现异常的Full GC

如下是第6次Full GC，这次Full GC实际耗时1.94秒，异常它来了。

第七次Full GC到来

最终程序卡死时的Full GC

分析

处理方法

1.服务器扩大内存为64G 32核

2.修改JVM默认的垃圾收集器(Parallel GC)，改为G1 或者 CMS。

3. 针对CMS 收集器

4. 结合GC 日志，我们还可以延长对象在eden驻留时间，减小老年代压力

处理原因

最终

写在 2023-10-14

公告