Arthas 和 GC 的那点事：动态日志，强制 GC

[hengyunabc]

Arthas是 Alibaba 开源的 Java 诊断工具，深受开发者喜爱。

• Github： https://github.com/alibaba/arthas
• 文档：https://arthas.aliyun.com/doc/

一、线上应用怎么动态打印 GC 日志？

小白正在上班摸鱼，突然运维告警，线上应用突发 GC 问题，GC 时间变长，响应变慢。 火速登陆机器，想检查 GC 日志，忽然发现，线上应用 JVM 参数没有打印 GC 信息😂。

如果增加 JVM 参数，那么要重启应用，现场就没有了，怎么办？

Arthas 可以解决这个问题！

二、使用 dashboard 命令查看 GC 信息

在 dashboard 命令里可以直接看到 GC 的数据，次数和时间：

三、使用 vmoption 命令动态打开 GC 日志

• https://arthas.aliyun.com/doc/vmoption

$ vmoption PrintGC true
Successfully updated the vm option.
 NAME     BEFORE-VALUE  AFTER-VALUE
------------------------------------
 PrintGC  false         true

$ vmoption PrintGCDetails true
Successfully updated the vm option.
 NAME            BEFORE-VALUE  AFTER-VALUE
-------------------------------------------
 PrintGCDetails  false         true

打开上面两个选项之后，当应用发生 GC 时，就会在标准输出里打印 GC 日志。

四、使用 vmtool 强制 GC

• https://arthas.aliyun.com/doc/vmtool

$ vmtool --action forceGc

然后查看应用的标准输出，可以发现有 GC 日志：

[GC (JvmtiEnv ForceGarbageCollection) [PSYoungGen: 2184K->352K(76288K)] 19298K->17474K(166912K), 0.0011562 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
[Full GC (JvmtiEnv ForceGarbageCollection) [PSYoungGen: 352K->0K(76288K)] [ParOldGen: 17122K->16100K(90112K)] 17474K->16100K(166400K), [Metaspace: 20688K->20688K(1069056K)], 0.0232947 secs] [Times: user=0.14 sys=0.01, real=0.03 secs]

五、更多 GC 开关

5.1 打印 GC ID

$ vmoption PrintGCID true
Successfully updated the vm option.
 NAME       BEFORE-VALUE  AFTER-VALUE
--------------------------------------
 PrintGCID  false         true

则 GC 日志里会有#的 ID：

#5: [GC (JvmtiEnv ForceGarbageCollection) [PSYoungGen: 9219K->352K(76288K)] 25319K->16460K(166400K), 0.0017758 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

5.2 打印 GC 时间戳

$ vmoption PrintGCDateStamps true
Successfully updated the vm option.
 NAME               BEFORE-VALUE  AFTER-VALUE
----------------------------------------------
 PrintGCDateStamps  false         true

则 GC 日志会带上时间：

2021-07-22T17:54:08.820-0800: [GC (JvmtiEnv ForceGarbageCollection)  21111K->16334K(160768K), 0.0015284 secs]
2021-07-22T17:54:08.822-0800: [Full GC (JvmtiEnv ForceGarbageCollection)  16334K->16105K(158720K), 0.0191751 secs]

$ vmoption PrintGCTimeStamps true
Successfully updated the vm option.
 NAME               BEFORE-VALUE  AFTER-VALUE
----------------------------------------------
 PrintGCTimeStamps  false         true

则 GC 日志会带上应用启动时间：

1087.493: [GC (JvmtiEnv ForceGarbageCollection)  18416K->16360K(154624K), 0.0014647 secs]
1087.494: [Full GC (JvmtiEnv ForceGarbageCollection)  16360K->16105K(153600K), 0.0164804 secs]

5.3 在 GC 前后，执行 heapdump

在排查 GC 问题时，我们有时需要对比 GC 前后，生成 heapdump 文件，然后再做对比。

• 打开 HeapDumpBeforeFullGC 开关，可以在 GC 前生成 heapdump 文件
• 打开 HeapDumpAfterFullGC 开关，可以在 GC 结束后生成 heapdump 文件

$ vmoption HeapDumpBeforeFullGC true
Successfully updated the vm option.
 NAME                  BEFORE-VALUE  AFTER-VALUE
-------------------------------------------------
 HeapDumpBeforeFullGC  false         true
$ vmtool --action forceGc

再使用vmtool --action forceGc强制 GC，则可以在 GC 日志中发现 heapdump 信息，并且在应用目录下会生成 heapdump hprof 文件：

#9: [Heap Dump (before full gc): Dumping heap to java_pid69445.hprof ...
Heap dump file created [23915304 bytes in 0.107 secs]

再使用其它堆分析软件，对比两个 heapdump 文件，就可以知道 GC 到底回收了哪些对象。

5.4 在 GC 前后，打印类直方图

排查 GC 问题时，我们有时需要统计每个类加载的数量和占用内存大小。

• 打开PrintClassHistogramBeforeFullGC开关，可以在 GC 前打印类直方图
• 打开PrintClassHistogramAfterFullGC开关，可以在 GC 结束后打印类直方图

$ vmoption PrintClassHistogramBeforeFullGC true
Successfully updated the vm option.
 NAME                             BEFORE-VALUE  AFTER-VALUE
------------------------------------------------------------
 PrintClassHistogramBeforeFullGC  false         true
$ vmtool --action forceGc

再使用vmtool --action forceGc强制 GC，在 GC 日志中会打印类直方图，可以直观知道每个类的 instances 数量，占用内存大小：

#13: [Class Histogram (before full gc):
 num     #instances         #bytes  class name
----------------------------------------------
   1:         24519        5783400  [C
   2:          5648        5102712  [B
   3:          3685         888128  [Ljava.lang.Object;
   4:          3255         619560  [I
   5:         24263         582312  java.lang.String
   6:          4227         475320  java.lang.Class
   7:          1288         402112  [Ljava.util.HashMap$Node;
   8:            75         296160  [Ljava.nio.channels.SelectionKey;
   9:          6759         216288  java.util.HashMap$Node
  10:          2069         182072  java.lang.reflect.Method
  11:          3326         133040  java.util.LinkedHashMap$Entry

六、总结

• 通过dashboard命令查看 GC 统计信息
• 通过vmoption命令动态打开 GC 开关，GC 前后 heapdump，打印类直方图
• 通过vmtool命令可以强制 GC

招聘

最后打个广告，我们正在寻找小伙伴，特别是深圳的同学，欢迎大家加入。

• 阿里云-云原生-中间件招聘（深圳 /杭州）

[wdlth]

感觉改 JVM 开关配置和 jinfo 的功能差不多