V2EX = way to explore
V2EX 是一个关于分享和探索的地方
现在注册
已注册用户请  登录
hengyunabc
V2EX  ›  Java

Arthas 和 GC 的那点事:动态日志,强制 GC

  •  
  •   hengyunabc ·
    hengyunabc · 2021-07-30 10:51:02 +08:00 · 3883 次点击
    这是一个创建于 973 天前的主题,其中的信息可能已经有所发展或是发生改变。

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

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

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

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

    Arthas 可以解决这个问题!

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

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

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

    $ 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

    $ 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

    招聘

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

    1 条回复    2021-07-31 19:27:22 +08:00
    wdlth
        1
    wdlth  
       2021-07-31 19:27:22 +08:00
    感觉改 JVM 开关配置和 jinfo 的功能差不多
    关于   ·   帮助文档   ·   博客   ·   API   ·   FAQ   ·   我们的愿景   ·   实用小工具   ·   2820 人在线   最高记录 6543   ·     Select Language
    创意工作者们的社区
    World is powered by solitude
    VERSION: 3.9.8.5 · 24ms · UTC 13:24 · PVG 21:24 · LAX 06:24 · JFK 09:24
    Developed with CodeLauncher
    ♥ Do have faith in what you're doing.