近期工作中,在线上碰到一个问题:用户现场反应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,它为了达到目标的暂停时间,会选中回收效益比较高的年轻代和部分老年代进行回收

更多推荐