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

2021/6/19 17:29:23

本文主要是介绍《深入理解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驻留时间,减小老年代压力
    • 处理原因
  • 最终

问题

我们公司的程序是的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无法回收内存空间,程序卡死。

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

  1. 选择 并发 方式 的 GC 收集器(CMS 、G1),减少STW操作(Stop The Word);
  2. 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收集器再适当调优就能解决该问题。



这篇关于《深入理解Java虚拟机》(五) JVM调优案例的文章就介绍到这儿,希望我们推荐的文章对大家有所帮助,也希望大家多多支持为之网!


扫一扫关注最新编程教程