Java 基本功之内存诊断
近期工作中,在线上碰到一个问题:用户现场反应80 页面报错:服务异常。以为是用户在页面操作大表,导致页面没接口超时,报服务异常。于是问用户要了远程后,发现几个问题:
1、80页面持续报服务异常。甚至出现异常时,80页面的所有菜单都没有了。
2、jps 查看进程以及是否监听的端口号发现都正常
问题排查:
1、top 查看资源占用情况,发现可用内存还有20G+;CPU利用率也不是非常高
2、从注册中心查看服务,发现注册中心也没有服务
3、查询操作系统日志,除了机器安装的软件特征日志以外,没发现其他异常
4、查看程序启动lib.log等日志一无所获
5、通过其他监控手段监控服务状态的接口,发现接口可以正常返回,但是耗时非常慢。说明程序也能正常响应
6、想通过arthas 查看程序运行状态,然而,JVM根本就没响应。。。
没办法,既然高级武器不能用,那只能使用jvm 自带的工具了。由于进程占用CPU并不是很高,于是自然怀疑是否可能是内存问题导致。于是,通过jmap 查询内存较多的对象
su -s /bin/bash -c "jmap -histo:live 30049 | head -n 20" app
发现有个StrategyRange对象占用空间比较多,比较可疑。但是这也无法定位到问题。于是查看gc 情况:
su -s /bin/bash -c "jstat -gc 30049 10 5" app
发现居然有FGC。然后查看gc 日志:
2025-08-07T11:34:31.693+0800: 246944.431: [GC pause (G1 Evacuation Pause) (young), 0.0162726 secs]
[Parallel Time: 9.9 ms, GC Workers: 23]
[GC Worker Start (ms): Min: 246944431.4, Avg: 246944431.8, Max: 246944432.2, Diff: 0.8]
[Ext Root Scanning (ms): Min: 2.4, Avg: 3.1, Max: 8.6, Diff: 6.2, Sum: 71.2]
[Update RS (ms): Min: 0.0, Avg: 0.2, Max: 0.5, Diff: 0.5, Sum: 3.5]
[Processed Buffers: Min: 0, Avg: 0.1, Max: 1, Diff: 1, Sum: 2]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 1.1]
[Termination (ms): Min: 0.0, Avg: 5.0, Max: 5.4, Diff: 5.4, Sum: 113.9]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 23]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3]
[GC Worker Total (ms): Min: 7.8, Avg: 8.3, Max: 8.6, Diff: 0.8, Sum: 190.2]
[GC Worker End (ms): Min: 246944440.0, Avg: 246944440.0, Max: 246944440.1, Diff: 0.1]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 1.8 ms]
[Other: 4.5 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 1.9 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 1.4 ms]
[Humongous Register: 0.3 ms]
[Humongous Reclaim: 0.3 ms]
[Free CSet: 0.1 ms]
[Eden: 0.0B(1224.0M)->0.0B(1224.0M) Survivors: 0.0B->0.0B Heap: 24349.0M(24576.0M)->24349.0M(24576.0M)]
[Times: user=0.19 sys=0.00, real=0.01 secs]
2025-08-07T11:34:31.717+0800: 246944.455: [Full GC (Allocation Failure) 24402M->14613M(24576M), 55.2429419 secs]
注意GC日志中几个关键字眼:
1、Full GC: 很明显Full GC 肯定是发生了,并且持续时间接近1分钟
2、Eden 区基本上相当于没有,所有的数据集中在老年代(使用的G1,年轻代和老年代动态会调整):0.0B(1224.0M)->0.0B(1224.0M) Survivors: 0.0B->0.0B
3、老年代的内存基本上没有可以被回收的,Heap堆再gc前后没有改变:24349.0M(24576.0M)->24349.0M(24576.0M)
4、Humongous Register和Humongous Reclaim ,说明有大对象产生,被放到了Humongous。
很明显:这种Full gc 由于回收不了内存,那么gc 肯定会再次开启回收,如果再次回收不了多少内存,那么再次发生Full GC,如此往复
dump内存分析
使用jmap 将dump下内存快照,然后分析:
从上图看,占用500~700多M的居然有这么多。占用218M的也有10 好几个。
再看看这么大的对象存的是什么数据:
查看相应的堆栈信息:
根据堆栈信息查看代码:
public List<String> getIdsForContainer(int group) {
List<String> result = Lists.newArrayList();
List<String> containerIds = getContainerIds(group);
List<String> targetIds = Lists.newArrayList(containerIds);
List<RangeHistory> rangeHistories = rangeHistoryService.find(HistoryQuery
.builder().targetIds(targetIds).build());
rangeHistories.stream().map(RangeHistory::getId).forEach(result::add);
return result;
}
问题就出在了angeHistoryService.find上,当targetIds集合为空时,会查询到所有结果返回。找到问题症结所在,修复就不再赘述。
问题原因反思:
我们工程中,类似这种用某个集合查询,但是当要查询的集合为空时,会查到所有,这类问题很早就知道,但是在实际写业务时,却很难在每个地方要查询DB时先判空...
总结
通过以上问题,再复习下G1垃圾回收的特点:
1、新生代和老年代大小并不是固定的
2、大对象直接进入老年代。如果数组、列表等,他们申请内存时,需要一整块连续的内存空间,因此很可能直接进入老年代。大对象指的是超过RegionSize 大小的一半的对象
3、Humongous 用来存放大对象,那么它一定是老年代
4、回收老年代,并不一定都通过Full gc 。如G1中,存在Mixed gc,它为了达到目标的暂停时间,会选中回收效益比较高的年轻代和部分老年代进行回收
更多推荐


所有评论(0)