线上FullGC问题排查实践——手把手教你排查线上问题

fullgc,问题,排查,实践,手把手 · 浏览次数 : 550

小编点评

**代码分析** 代码分析涉及到以下问题: * 如何解决内存溢出问题? * 如何定位代码中的问题? * 如何推断代码问题的真正原因? **解决方法** **1. 解决内存溢出问题** * 通过设置大对象的大小限制,降低大对象的创建频率。 * 使用缓存技术,减少对大对象的反复访问。 * 优化代码,减少大对象的内存使用。 **2. 定位代码中的问题** * 使用性能分析工具,如 JProfiler,监控代码运行的性能。 * 通过代码分析,找到代码中的异常或错误。 * 使用内存分析工具,例如 heapdump,分析大对象堆栈。 **3. 推断代码问题的真正原因** * 分析代码,找到代码中的异常或错误。 * 通过问题排查总结,找到问题的真正原因。 * 通过其他现象推演猜测代码问题的真正原因。 **4. 代码分析工具** * JProfiler:直连线上jvm,监控代码运行的性能。 * dump:保存堆快照后离线分析。 * heapdump:分析大对象堆栈。 **5. 代码分析技巧** * 优先分析问题,解决问题前先解决问题。 * 使用问题排查总结,找到问题的真正原因。 * 推断代码问题的真正原因,以找到问题的真正原因。

正文

作者:京东科技 韩国凯

一、问题发现与排查

1.1 找到问题原因

问题起因是我们收到了jdos的容器CPU告警,CPU使用率已经达到104%

image-20230421152602849

观察该机器日志发现,此时有很多线程在执行跑批任务。正常来说,跑批任务是低CPU高内存型,所以此时考虑是FullGC引起的大量CPU占用(之前有类似情况,告知用户后重启应用后解决问题)。

通过泰山查看该机器内存使用情况:

image-20230421152933510

可以看到CPU确实使用率偏高,但是内存使用率并不高,只有62%,属于正常范围内。

到这里其实就有点迷惑了,按道理来说此时内存应该已经打满才对。

后面根据其他指标,例如流量的突然进入也怀疑过是jsf接口被突然大量调用导致的cpu占满,所以内存使用率不高,不过后面都慢慢排除了。其实在这里就有点一筹莫展了,现象与猜测不符,只有CPU增长而没有内存增长,那么什么原因会导致单方面CPU增长?然后又朝这个方向排查了半天也都被否定了。

后面突然意识到,会不会是监控有“问题”?

换句话说应该是我们看到的监控有问题,这里的监控是机器的监控,而不是JVM的监控!

JVM的使用的CPU是在机器上能体现出来的,而JVM的堆内存高额使用之后在机器上体现的并不是很明显。

遂去sgm查看对应节点的jvm相关情况:

image-20230421154928774

可以看到我们的堆内存老年代确实有过被打满然后又清理后的情况,查看此时的CPU使用情况也可以与GC时间对应上。

那么此时可以确定,是Full GC引起的问题。

1.2 找到FULL GC的原因

我们首先dump出了gc前后的堆内存快照,

然后使用JPofiler进行内存分析。(JProfiler是一款堆内存分析工具,可以直接连接线上jvm实时查看相关信息,也可以分析dump出来的堆内存快照,对某一时刻的堆内存情况进行分析)

首先将我们dump出来的文件解压,修改后缀名.bin,然后打开即可。(我们使用行云上自带的dump小工具,也可以自己去机器上通过命令手工dump文件)

image-20230421155755209

首先选择Biggest Objects,查看当时堆内存中最大的几个对象。

从图中可以看出,四个List对象就占据了近900MB的内存,而我们刚刚看到堆内存最大也只有1.3GB,因此再加上其他的对象,很容易就会把老年代占满引发full gc的问题。

image-20230421160135305

选择其中一个最大的对象作为我们要查看的对象

这个时候我们已经可以定位到对应的大内存对象对应的位置:

image-20230421160241646

其实至此我们已经能够大概定位出问题所在,如果还是不确定的话,可以查看具体的对象信息,方法如下:

image-20230421160532920

可以看到我们的大List对象,其实内部是很多个Map对象,而每个Map对象中又有很多键值对。

在这里也可以看到Map中的相关属性信息。

也可以在以下界面直接看到相关信息:

image-20230421160715617

然后一路点下去就可以看到对应的属性。

至此,我们理论上已经找到了大对象在代码中的位置。

二、问题解决

2.1 找到大对象在代码中的位置与问题的根本原因

首先我们根据上述过程找到对应位置与逻辑

我们的项目中大概逻辑是这样的:

  1. 首先会解析用户上传的Excel样本,并将其加载到内存中作为一个List变量,即我们上述看到的变量。一个20w的样本,此时字段数量有a个,大概占用空间100mb左右。
  2. 然后遍历循环用户样本,根据用户样本中的数据,再增加一些额外的请求数据,根据此数据请求相关结果。此时字段数量有a+n个,占用空间已经在200mb左右。
  3. 循环完成后将此200mb的数据存入缓存。
  4. 开始生成excel,将200mb数据从缓存中取出,并根据之前记录的a个字段,取出初始的样本字段填充至excel。

用流程图表示为:

jvmgc-Page-1.drawio

结合一些具体排查问题的图片:

image-20230421172512115

其中一个现象是每次gc后的最小内存正在逐步变大,对应上述步骤中第二步,内存正在逐步膨胀。

结论

将用户上传的excel样本加载到内存中,并将其作为一个List<Map<String, String>>的结构存储起来,首先一个20mb的excel文件以此方式存储会膨胀占用120mb左右堆内存,此步骤会大量占用堆内存,并且因为任务逻辑原因,该大对象内存会在jvm中存在长达4-12小时之久,导致一但任务过多,jvm堆内存很容易被打满。

这里列举了为什么使用HashMap会导致内存膨胀,其主要原因是存储空间效率比较低:

一个Long对象占内存计算:在HashMap<Long,Long>结构中,只有Key和Value所存放的两个长整型数据是有效数据,共16字节(2×8字节)。这两个长整型数据包装成java.lang.Long对象之后,就分别具有8字节的MarkWord、8字节的Klass指针,再加8字节存储数据的long值(一个包装对象占24字节)。

然后这2个Long对象组成Map.Entry之后,又多了16字节的对象头(8字节MarkWord+8字节Klass指针=16字节),然后一个8字节的next字段和4字节的int型的hash字段(8字节next指针+4字节hash字段+4字节填充=16字节),为了对齐,还必须添加4字节的空白填充,最后还有HashMap中对这个Entry的8字节的引用,这样增加两个长整型数字,实际耗费的内存为(Long(24byte)×2)+Entry(32byte)+HashMapRef(8byte)=88byte,空间效率为有效数据除以全部内存空间,即16字节/88字节=18%。

——《深入理解Java虚拟机》5.2.6

以下是刚上传的excel中dump出的堆内存对象,其占用的内存达到了128mb,而上传的excel实际只有17.11mb。

image-20230423145825354

image-20230423145801632

空间效率17.1mb/128mb≈13.4%

2.2 如何解决此问题

暂且不讨论上述流程是否合理,解决办法一般可以分为两类,一类是治本,即不把该对象放入jvm内存中,转而存入缓存中,不在内存中则大对象问题自然迎刃而解。另一类是治标,即缩小该大内存对象,在日常使用场景下使其一般不会触发频繁的full gc问题。

两种方式各有优劣:

2.2.1 激进治疗:不把他存入内存

解决逻辑也很简单,例如在加载数据时,将其按照样本加载数据一条一条存入redis缓存,然后我们只需要知道样本中有多少的数量,按照数量的先后顺序从缓存中取出数据,即可解决该问题。

优点:可以从根本上解决此问题,以后基本上不会存在该问题,数据量再大只需要添加相应的redis资源即可。

缺点:首先会增加许多redis缓存空间消耗,其次从显示考虑对于我们项目来说,此处代码古老且晦涩难懂,改动需要较大工作量与回归测试。

伏羲运营后台fullgc-第 2 页.drawio

2.2.2 保守治疗:缩减其数据量

分析2.1的上述流程,首先第三步是完全没必要的,先存入缓存再取出,额外占用缓存空间。(猜测系历史问题,此处不再深究)。

其次是在第二步中,多出来的字段n,在请求结束后该字段就已经无用了,因此可以考虑在请求结束后删除无用字段。

此时也有两种解决方案,一种是只删除无用字段缩减其map大小,然后将其作为参数传递给生成excel使用;另一种方式是请求完成直接删除该map,然后在生成excel时再重新读取用户上传的excel样本。

优点:改动较小,不需要太复杂的回归测试

缺点:在极端大数据量情况下,仍有可能出现full gc的情况

jvmgc-第 3 页.drawio

具体实现方式就不展开了。

其中一种实现方式

//获取有用的字段
String[] colEnNames = (String[]) colNameMap.get(Constant.BATCH_COL_EN_NAMES);
List<String> colList = Arrays.asList(colEnNames);
//去除无用的字段
param.keySet().removeIf(key -> !colList.contains(key));

三、拓展思考

首先本文中监控图是在复现当时场景时人为制造的gc常见。

在cpu使用率图中,大家可以观察到cpu使用率上升时间确实跟gc的时间相吻合,但是并没有出现当时场景中的104%的CPU使用率

image-20230423103730420

image-20230423103800435

其实直接原因比较简单,就是因为系统虽然出现了full gc,但是并没有频繁出现。

小范围低频率的full gc不太会引起系统的cpu飙升,这也是我们所看到的现象。

那么当时的场景是什么原因呢?

image-20230423105534963

我们上文提到过,我们在堆内存中的大对象是会随着任务的进行逐步膨胀的,那么当我们的任务足够多,时间足够长,就有可能导致每次full gc后可用空间变得越来越小,当可用空间小到一定程度之后就,每次full gc完成之后发现空间还是不够使用,就会触发下一次的gc,从而导致最终结果的频繁发生gc,引起cpu频率的飙升不下。

四、问题排查总结

  • 当我们遇到线上cpu使用率过高的情况时,可以先查看是否是full gc引起的问题,注意要看的是jvm的监控,或者使用jstat相关命令查看。不要被机器内存监控所误导。
  • 如果确定是gc引起的问题,可以通过JProfiler直连线上jvm或者使用dump保存堆快照后离线分析。
  • 首先可以找到最大的对象,一般情况下是大对象引起的full gc。还有一种情况是,不像这么明显是四个大对象,也可能是比较均衡的十几个50mb的对象,具体情况还需要具体分析。
  • 通过上述工具找到确定有问题的对象后找到其堆栈对应的代码位置,通过代码分析找到问题的具体原因,通过其他现象推演猜测是否正确,进而找到问题的真正原因。
  • 根据问题的原因解决此问题。

当然,上述只是不算很复杂的排查情况,不同的系统肯定有不同的内存情况,我们应当具体问题具体分析,而从此次问题中可以学到的就是如果排查解决问题的思路。

与线上FullGC问题排查实践——手把手教你排查线上问题相似的内容:

线上FullGC问题排查实践——手把手教你排查线上问题

作者:京东科技 韩国凯 一、问题发现与排查 1.1 找到问题原因 问题起因是我们收到了jdos的容器CPU告警,CPU使用率已经达到104% 观察该机器日志发现,此时有很多线程在执行跑批任务。正常来说,跑批任务是低CPU高内存型,所以此时考虑是FullGC引起的大量CPU占用(之前有类似情况,告知用

[转帖]JVM 使用mat分析Dump文件排查大对象解决系统full GC问题

https://www.cnblogs.com/east7/p/16989436.html 摘要:介绍内存分析工具Mat查找大对象的使用方法,定位full GC根源,拉升系统吞吐量,避免内存泄漏。 引言 线上服务器频繁发生full GC,直接拉低系统吞吐量,甚至OOM。今天我们来一起学习一下如何利用

[转帖]JVM 使用mat分析Dump文件排查大对象解决系统full GC问题

https://www.cnblogs.com/east7/p/16989436.html 摘要:介绍内存分析工具Mat查找大对象的使用方法,定位full GC根源,拉升系统吞吐量,避免内存泄漏。 引言 线上服务器频繁发生full GC,直接拉低系统吞吐量,甚至OOM。今天我们来一起学习一下如何利用

[转帖]JVM 使用mat分析Dump文件排查大对象解决系统full GC问题

https://www.cnblogs.com/east7/p/16989436.html 摘要:介绍内存分析工具Mat查找大对象的使用方法,定位full GC根源,拉升系统吞吐量,避免内存泄漏。 引言 线上服务器频繁发生full GC,直接拉低系统吞吐量,甚至OOM。今天我们来一起学习一下如何利用

一次JVM GC长暂停的排查过程

作者:京东科技 徐传乐 背景 在高并发下,Java程序的GC问题属于很典型的一类问题,带来的影响往往会被进一步放大。不管是「GC频率过快」还是「GC耗时太长」,由于GC期间都存在Stop The World问题,因此很容易导致服务超时,引发性能问题。 事情最初是线上某应用垃圾收集出现Full GC异

[转帖]线上Java 高CPU占用、高内存占用排查思路

一、前言 处理过线上问题的同学基本上都会遇到系统突然运行缓慢,CPU 100%,以及Full GC次数过多的问题。当然,这些问题的最终导致的直观现象就是系统运行缓慢,并且有大量的报警。本文主要针对系统运行缓慢这一问题,提供该问题的排查思路,从而定位出问题的代码点,进而提供解决该问题的思路。 二、分析

【转帖】Java Full GC (Ergonomics) 的排查

文章目录 1. Full GC (Ergonomics)1.1 Java 进程一直进行 Full GC1.2 Full GC 的原因1.3 检查堆占用 2. 代码检查3. 解决方式 1. Full GC (Ergonomics) 1.1 Java 进程一直进行 Full GC 例行检查线上运行的 J

[转帖]线上环境 Linux 系统调用追踪

线上环境 Linux 系统调用追踪 PingCAP 提到如何动态追踪进程中的系统调用,相信大家第一时间都能想到 strace,它的基本用法非常简单,非常适合用来解决 “为什么这个软件无法在这台机器上运行?” 这类问题。但如果需要分析线上服务 (特别是延迟敏感型)的某些系统调用的延迟时,strace

线上问题排查--进程重启失败,最后发现是忘了cd

# 背景 我前面写了几篇文章,讲c3p0数据库连接池发生了连接泄露,但是随机出现,难以确定根因,最终呢,为了快速解决问题,我是先写了个shell脚本,脚本主要是检测服务的接口访问日志,看看过去的30s内是不是接口几乎都超时了,如果是的话,咱们就重启服务。然后把这个shell加入到了crontab里,

MySQL innoDB 间隙锁产生的死锁问题

线上经常偶发死锁问题,当时处理一张表,也没有联表处理,但是有两个mq入口,并且消息体存在一样的情况,频率还不是很低,这么一个背景,我非常容易怀疑到,两个消息同时近到这一个事务里面导致的,但是是偶发的,又模拟不出来什么场景会导致死锁,只能进行代码分析,问题还原的方式去排查问题。