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

客官°小女子只卖身不卖艺 2024-03-22 13:50 23阅读 0赞

### 一、问题发现与排查 ###

#### 1.1 找到问题原因 ####

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

![4d3f5a4c65a634e120d0d4440d9b8c0f.png][]

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

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

![c7fe13088a90547a93480dfd481b5590.png][]

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

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

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

后面突然意识到，**会不会是监控有 “问题”？**

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

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

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

![42598b12471e2235448bd1f733bd80c6.png][]

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

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

#### 1.2 找到 FULL GC 的原因 ####

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

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

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

![22d2aafa4818b0bdcb24ab9fd54f4901.png][]

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

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

![de87c37fdc2fde756cdc8612a005188c.png][]

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

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

![01a05c1e8445841f251e916e1164424f.png][]

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

![aab9b84df66959aa6782aba9c7d89613.png][]

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

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

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

![9c525abc5fc5631f840dc844b49a3385.png][]

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

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

### 二、问题解决 ###

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

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

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

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

用流程图表示为：

![9e310505d45f4de7a154bc3fb5901481.png][]

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

![0776aca84cb194f99e0080b1b9bac47e.png][]

其中一个现象是每次 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。

![c23fb75aa8fa934a3a2d0572f6abc739.png][]

![a5d66d073854faf63543075c311b05cf.png][]

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

#### 2.2 如何解决此问题 ####

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

两种方式各有优劣：

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

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

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

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

![ba6794fdbab195b224edf9da21ecc797.png][]

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

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

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

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

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

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

![37f3baddc7089690b3233b1e4328a4d7.png][]

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

其中一种实现方式

//获取有用的字段
    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 使用率**。

![11b285ca170601a49d395abd43f46940.png][]

![7e06d4bbcd1e6771b7b5c0b2b21e4b8d.png][]

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

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

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

![429542b3c36ae98576ec2bb855c2c798.png][]

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

### 四、问题排查总结 ###

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

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

原文：

https://my.oschina.net/u/4090830/blog/8704836

[4d3f5a4c65a634e120d0d4440d9b8c0f.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/22/2eac421489894684818f737f7f7737b6.png
[c7fe13088a90547a93480dfd481b5590.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/22/edacd386619846cabe7fa5330a8d4f19.png
[42598b12471e2235448bd1f733bd80c6.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/22/5d8bd5d9f20d4439a1f46ed79a9af97e.png
[22d2aafa4818b0bdcb24ab9fd54f4901.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/22/1005e43b001740d481da9e4db1778874.png
[de87c37fdc2fde756cdc8612a005188c.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/22/adc0d83966b04525bbbab679f117e33b.png
[01a05c1e8445841f251e916e1164424f.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/22/31e2314523d2466f97f7477aed5c1dbd.png
[aab9b84df66959aa6782aba9c7d89613.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/22/718b31834bb64504b1354faafb58e4ca.png
[9c525abc5fc5631f840dc844b49a3385.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/22/cf6e289d3a3344cf892209cee0a9bfb0.png
[9e310505d45f4de7a154bc3fb5901481.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/22/c657797a91d14134a0a7da807933d05b.png
[0776aca84cb194f99e0080b1b9bac47e.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/22/01dd5e2930e8456ca0678539c3089510.png
[c23fb75aa8fa934a3a2d0572f6abc739.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/22/4f3ddf8e2b2444678e2a1e51142c4640.png
[a5d66d073854faf63543075c311b05cf.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/22/8d08c97824bb4e0c8eb8ee41f22dba9d.png
[ba6794fdbab195b224edf9da21ecc797.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/22/8e32e0420ab245e5a7f50c364da100eb.png
[37f3baddc7089690b3233b1e4328a4d7.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/22/1e632c2df35e4af6872537263dfb000b.png
[11b285ca170601a49d395abd43f46940.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/22/b0213026cdbb454f91139bc14e1ab2b0.png
[7e06d4bbcd1e6771b7b5c0b2b21e4b8d.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/22/9db61353dbcf44e094088bfe02f6f9b9.png
[429542b3c36ae98576ec2bb855c2c798.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/22/2058fa2e83bc417b8d146ed2017112cd.png