线上每天某个时间段频繁 FGC,导致 CPU 异常高

V2EX = way to explore

V2EX 是一个关于分享和探索的地方

现在注册

已注册用户请登录

这是一个创建于 1657 天前的主题，其中的信息可能已经有所发展或是发生改变。

每天基本上到了某个时间段,客户使用频繁后,线上 CPU 就会往上蹭. 我尝试使用 jstat 去查看 gc 的情况,发现当 E 区满了之后,直接 FGC, S0,S1 在这段时间永远都是 0.00, O 区基本上一直都是 99%以上的状态.

# jstat -gcutil 153221 1000 100
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT                                                                                                         
 0.00   0.00  32.73  99.33  92.54  85.47  15969  450.680  4209 15061.630 15512.                                                                                                       309
 0.00   0.00  99.85  99.33  92.54  85.47  15969  450.680  4209 15061.630 15512.                                                                                                       309
 0.00   0.00  76.47  99.33  92.54  85.47  15969  450.680  4210 15063.630 15512.                                                                                                       309
 0.00   0.00  96.83  99.33  92.54  85.47  15969  450.680  4210 15063.630 15512.309
 0.00   0.00  88.25  99.33  92.54  85.47  15969  450.680  4211 15065.630 15512.309
 0.00   0.00  99.70  99.33  92.54  85.47  15969  450.680  4211 15065.630 15512.309

3 秒中一次 FGC,大部分 CPU 都用在 GC 线程上面. 过了这段时间后系统就会恢复正常,CPU 就会恢复稳定. 现在想请教下各位: 什么情况下会造成 Eden 区满了之后,直接触发 Full GC, 而不是 YGC. 另外,即便是现在 CPU 降下来了, gc 正常了, ps_old_gen 使用率依旧很高. (2685M/2731M), 如果是内存泄露那么不应该 CPU 一直都没法降下来吗?

请教下各位,遇到这种问题应该朝着什么方向去排查呢?

7 条回复 • 2020-07-24 21:57:12 +08:00

Jooooooooo

2020-05-16 14:27:04 +08:00

首先看下 jvm 配置, 是不是 s 区装不下了所以被迫直接放进 old, 算一下大小

第二是既然 gc 之后使用率很高, 那踩点 dump, 看看内存是都是什么东西, 找准业务特有相关的东西去看. 特别是还可以在低峰期正常的时候同时 dump 一份对比看看有什么对象是异常时期特有的

第三是如果某个固定时间发生这种异常一般要么是随着业务运行, 内存刚好需要做这样的调整, 要么就是存在业务特点, 分析一下那个时间段有没有特殊的业务(比如秒杀活动, 定时任务等等)

第四是看看异常时期的日志, 也辅助定位是不是存在特殊的逻辑

第五贴一下完整的 gc log, 特别是带有 young 区分代信息的

Solace202

2020-05-16 15:57:45 +08:00 via iPhone

没有 young gc 可能是 survivor 区放不下直接 full gc 。一楼说的对，full gc 了直接用 jamp 把堆栈 dump 下来，然后 eclipse memory analyser 工具看看啥东西一直那么多一直 full gc，然后优化代码。

aizya

2020-05-16 17:52:56 +08:00

@Jooooooooo GC log 能看出什么原因吗

gc log 如下所示:

```
[Full GC (Ergonomics) 3881881K->2889968K(4038144K), 4.5727780 secs]
[Full GC (Ergonomics) 3881681K->2889026K(4038144K), 3.0774469 secs]
[Full GC (Ergonomics) 3881614K->2888641K(4038144K), 2.2580244 secs]
[Full GC (Ergonomics) 3881614K->2887646K(4038144K), 4.2011123 secs]
17:46:48,926
[Full GC (Ergonomics) 3881614K->2887135K(4038144K), 2.7401695 secs]
[Full GC (Ergonomics) 3881612K->2886768K(4038144K), 4.0454051 secs]
[Full GC (Ergonomics) 3881612K->2887188K(4038144K), 2.3936678 secs]
[Full GC (Ergonomics) 3881608K->2887642K(4038144K), 4.0567923 secs]
[Full GC (Ergonomics) 3881918K->2886507K(4038144K), 4.6593080 secs]
[Full GC (Ergonomics) 3881783K->2886918K(4038144K), 4.0624945 secs]
17:47:38,528
[Full GC (Ergonomics) 3881782K->2865376K(4038144K), 0.8624403 secs]
[Full GC (Ergonomics) 3881694K->2865692K(4038144K), 2.9422862 secs]
[Full GC (Ergonomics) [PSYoungGen: 1085440K->69778K(1241600K)] [ParOldGen: 2796159K->2796144K(2796544K)] 3881599K->2865922K(4038144K), [Metaspace: 238529K->238529K(1271808K)], 3.3878363 secs] [Times: user=71.81 sys=0.39, real=3.39 secs]
[Full GC (Ergonomics) [PSYoungGen: 1085440K->71060K(1241600K)] [ParOldGen: 2796144K->2796064K(2796544K)] 3881584K->2867125K(4038144K), [Metaspace: 238529K->238529K(1271808K)], 4.3924844 secs] [Times: user=93.60 sys=0.58, real=4.40 secs]
17:48:10,361
17:48:13,784
17:48:13,831
[Full GC (Ergonomics) [PSYoungGen: 1085440K->78286K(1241600K)] [ParOldGen: 2796064K->2795878K(2796544K)] 3881504K->2874164K(4038144K), [Metaspace: 238529K->238529K(1271808K)], 4.7109424 secs] [Times: user=101.27 sys=0.58, real=4.71 secs]
[Full GC (Ergonomics) [PSYoungGen: 1085440K->83326K(1241600K)] [ParOldGen: 2795878K->2795708K(2796544K)] 3881318K->2879035K(4038144K), [Metaspace: 238529K->238529K(1271808K)], 4.0158977 secs] [Times: user=85.44 sys=0.50, real=4.01 secs]
[Full GC (Ergonomics) [PSYoungGen: 1085440K->82672K(1241600K)] [ParOldGen: 2795708K->2795707K(2796544K)] 3881148K->2878379K(4038144K), [Metaspace: 238529K->238529K(1271808K)], 4.2606693 secs] [Times: user=90.71 sys=0.57, real=4.26 secs]
17:48:31,473
[Full GC (Ergonomics) [PSYoungGen: 1085440K->110615K(1241600K)] [ParOldGen: 2795707K->2795655K(2796544K)] 3881147K->2906270K(4038144K), [Metaspace: 238529K->238529K(1271808K)], 4.5355769 secs] [Times: user=96.77 sys=0.61, real=4.54 secs]

```

Jooooooooo

2020-05-16 17:54:12 +08:00

你做下 dump 吧, 很明显 old 回收不了

aizya

2020-05-18 10:46:54 +08:00

@Jooooooooo 问题解决了,谢谢你, 用 MAT 分析后发现问题了.

tonniky

2020-06-10 11:43:59 +08:00

@aizya 请教下楼主，分析出的问题原因是啥？看这日志好奇怪啊。

aizya

2020-07-24 21:57:12 +08:00

@tonniky 主要是通过 jstat -gc 命令观察 fgc 太频繁,最终还是通过 MAT 找到出现内存泄露了. 这个日志 ParOldGen 在 FGC 前后基本上没有变化, 表示内存被某个东西占用了,没法释放.