GC耗时案例

youngGC耗时长

gc日志：

2020-11-13T11:23:46.075+0800: 246511.397: [GC2020-11-13T11:23:49.696+0800: 246515.018: [ParNew
Desired survivor size 107347968 bytes, new threshold 15 (max 15)
- age   1:   37600800 bytes,   37600800 total
- age   2:     644144 bytes,   38244944 total
- age   3:     413776 bytes,   38658720 total
- age   4:     368720 bytes,   39027440 total
- age   5:     111280 bytes,   39138720 total
- age   6:      30144 bytes,   39168864 total
- age   7:     274864 bytes,   39443728 total
- age   8:      80256 bytes,   39523984 total
- age   9:      90832 bytes,   39614816 total
- age  10:     150704 bytes,   39765520 total
- age  11:      44976 bytes,   39810496 total
- age  12:     114016 bytes,   39924512 total
- age  13:     309672 bytes,   40234184 total
- age  14:      73296 bytes,   40307480 total
- age  15:     227016 bytes,   40534496 total
: 1730709K->52157K(1887488K), 0.0440210 secs] 2947428K->1268934K(5033216K), 3.6648820 secs] [Times: user=0.23 sys=0.00, real=3.66 secs] 
2020-11-13T11:23:49.740+0800: 246515.062: Total time for which application threads were stopped: 3.6662720 seconds

可以看到墙钟时间real远大于用户态时间user+内核态时间sys。一般real远大于user和sys，有两个原因：

一是因为繁忙的IO操作：当程序存在繁忙的I/O操作（网络IO或磁盘IO）时，会让 real 时间大幅上升。因为在记录GC日志的时候，你的程序进行了磁盘读写，如果同一时间其他IO操作较重，则此时GC事件会延迟，进而影响了最终的 real 的值。
二是缺乏CPU资源：当程序本身是CPU密集型应用，或机器上其他进程占用了大量的CPU计算资源，则有可能会出现分配不到 CPU cycles的情况，这会让程序挂起，GC所花费的实际时间也将远大于 user + sys 的值。

首先查看CPU，发现没有异常，再查看磁盘使用情况，发现这段时间的磁盘占用很高，有一个很大的突刺，经过此可以初步判断是由于磁盘IO频繁导致gclog写入磁盘被阻塞。

解决办法可以将gc日志写入temfs，具体可以卸载文件夹：/dev/shm 下。

参考：

PreviousCodeCache NextJVM性能调优

Last updated 4 years ago

Was this helpful?

youngGC耗时长

gc日志：

2020-11-13T11:23:46.075+0800: 246511.397: [GC2020-11-13T11:23:49.696+0800: 246515.018: [ParNew
Desired survivor size 107347968 bytes, new threshold 15 (max 15)
- age   1:   37600800 bytes,   37600800 total
- age   2:     644144 bytes,   38244944 total
- age   3:     413776 bytes,   38658720 total
- age   4:     368720 bytes,   39027440 total
- age   5:     111280 bytes,   39138720 total
- age   6:      30144 bytes,   39168864 total
- age   7:     274864 bytes,   39443728 total
- age   8:      80256 bytes,   39523984 total
- age   9:      90832 bytes,   39614816 total
- age  10:     150704 bytes,   39765520 total
- age  11:      44976 bytes,   39810496 total
- age  12:     114016 bytes,   39924512 total
- age  13:     309672 bytes,   40234184 total
- age  14:      73296 bytes,   40307480 total
- age  15:     227016 bytes,   40534496 total
: 1730709K->52157K(1887488K), 0.0440210 secs] 2947428K->1268934K(5033216K), 3.6648820 secs] [Times: user=0.23 sys=0.00, real=3.66 secs] 
2020-11-13T11:23:49.740+0800: 246515.062: Total time for which application threads were stopped: 3.6662720 seconds

可以看到墙钟时间real远大于用户态时间user+内核态时间sys。一般real远大于user和sys，有两个原因：

一是因为繁忙的IO操作：当程序存在繁忙的I/O操作（网络IO或磁盘IO）时，会让 real 时间大幅上升。因为在记录GC日志的时候，你的程序进行了磁盘读写，如果同一时间其他IO操作较重，则此时GC事件会延迟，进而影响了最终的 real 的值。

二是缺乏CPU资源：当程序本身是CPU密集型应用，或机器上其他进程占用了大量的CPU计算资源，则有可能会出现分配不到 CPU cycles的情况，这会让程序挂起，GC所花费的实际时间也将远大于 user + sys 的值。

解决办法可以将gc日志写入temfs，具体可以卸载文件夹：/dev/shm 下。

参考：