JVM：突发问题时如何输出GC日志

你勾哥还是你勾哥
2,867 阅读2分钟

链接：mp.weixin.qq.com/s/Zl_2Ud83K… 作者：李国

更多干货关注公众号 勾勾的Java宇宙（Javagogo)

对于 JVM 突发 GC 问题，GC 日志能够帮我们找到问题的根源。

事故出现的时候，通常并不是那么温柔，你可能在半夜里就能接到报警电话。这个时候，再去看 jstat 已经来不及了，我们需要保留现场。这个便是看门狗的工作，看门狗可以通过设置一些 JVM 参数进行配置。

具体怎么实现呢？

Java 8

我们先看一下 JDK8 中的使用。

#!/bin/sh
LOG_DIR="/tmp/logs"
JAVA_OPT_LOG=" -verbose:gc"
JAVA_OPT_LOG="${JAVA_OPT_LOG} -XX:+PrintGCDetails"
JAVA_OPT_LOG="${JAVA_OPT_LOG} -XX:+PrintGCDateStamps"
JAVA_OPT_LOG="${JAVA_OPT_LOG} -XX:+PrintGCApplicationStoppedTime"
JAVA_OPT_LOG="${JAVA_OPT_LOG} -XX:+PrintTenuringDistribution"
JAVA_OPT_LOG="${JAVA_OPT_LOG} -Xloggc:${LOG_DIR}/gc_%p.log"
JAVA_OPT_OOM=" -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=${LOG_DIR} -XX:ErrorFile=${LOG_DIR}/hs_error_pid%p.log "
JAVA_OPT="${JAVA_OPT_LOG} ${JAVA_OPT_OOM}"
JAVA_OPT="${JAVA_OPT} -XX:-OmitStackTraceInFastThrow"

合成一行

-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps 
-XX:+PrintGCApplicationStoppedTime -XX:+PrintTenuringDistribution 
-Xloggc:/tmp/logs/gc_%p.log -XX:+HeapDumpOnOutOfMemoryError 
-XX:HeapDumpPath=/tmp/logs -XX:ErrorFile=/tmp/logs/hs_error_pid%p.log 
-XX:-OmitStackTraceInFastThrow

然后我们来解释一下这些参数——

  • -verbose:gc ：打印 GC 日志

  • PrintGCDetails：打印详细 GC 日志

  • PrintGCDateStamps：系统时间，更加可读

  • PrintGCTimeStamps ：JVM 启动时间

  • PrintGCApplicationStoppedTime：打印 STW 时间

  • PrintTenuringDistribution：打印对象年龄分布，对调优 MaxTenuringThreshold 参数帮助很大

  • loggc：将以上 GC 内容输出到文件中

再来看下 OOM 时的参数和意义——

  • HeapDumpOnOutOfMemoryError：OOM 时 Dump 信息，非常有用

  • HeapDumpPath：Dump 文件保存路径

  • ErrorFile：错误日志存放路径

  • OmitStackTraceInFastThrow：JVM 用来缩简日志输出

开启 OmitStackTraceInFastThrow 这个参数之后，如果你多次发生了空指针异常，将会打印以下信息。

java.lang.NullPointerException
java.lang.NullPointerException
java.lang.NullPointerException
java.lang.NullPointerException

在实际生产中，这个参数是默认开启的，这样就导致有时候排查问题非常不方便（很多研发对此无能为力），我们这里把它关闭，但这样它会输出所有的异常堆栈，日志会多很多。

Java 13

再看下 JDK 13 中的使用。

从 Java 9 开始，移除了 40 多个 GC 日志相关的参数，具体参见 JEP 158。所以这部分的日志配置有很大的变化。

看一下它的生成脚本。

#!/bin/sh
LOG_DIR="/tmp/logs"
JAVA_OPT_LOG=" -verbose:gc"
JAVA_OPT_LOG="${JAVA_OPT_LOG} -Xlog:gc,gc+ref=debug,gc+heap=debug,gc+age=trace:file=${LOG_DIR}/gc_%p.log:tags,uptime,time,level"
JAVA_OPT_LOG="${JAVA_OPT_LOG} -Xlog:safepoint:file=${LOG_DIR}/safepoint_%p.log:tags,uptime,time,level"
JAVA_OPT_OOM=" -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=${LOG_DIR} -XX:ErrorFile=${LOG_DIR}/hs_error_pid%p.log "
JAVA_OPT="${JAVA_OPT_LOG} ${JAVA_OPT_OOM}"
JAVA_OPT="${JAVA_OPT} -XX:-OmitStackTraceInFastThrow"
echo $JAVA_OPT

合成一行展示

-verbose:gc -Xlog:gc,gc+ref=debug,gc+heap=debug,gc+age=trace:file
=/tmp/logs/gc_%p.log:tags,uptime,time,level -Xlog:safepoint:file=/tmp
/logs/safepoint_%p.log:tags,uptime,time,level -XX:+HeapDumpOnOutOfMemoryError 
-XX:HeapDumpPath=/tmp/logs -XX:ErrorFile=/tmp/logs/hs_error_pid%p.log 
-XX:-OmitStackTraceInFastThrow

可以看到 GC 日志的打印方式，已经完全不一样，但是比以前的日志参数规整了许多。

我们除了输出 GC 日志，还输出了 safepoint 的日志。这个日志对我们分析问题也很重要，那什么叫 safepoint 呢？

safepoint 是 JVM 中非常重要的一个概念，指的是可以安全地暂停线程的点。

当发生 GC 时，用户线程必须全部停下来，才可以进行垃圾回收，这个状态我们可以认为 JVM 是安全的（safe），整个堆的状态是稳定的。

image.png

如果在 GC 前，有线程迟迟进入不了 safepoint，那么整个 JVM 都在等待这个阻塞的线程，会造成了整体 GC 的时间变长。

所以并不是只有 GC 会挂起 JVM，进入 safepoint 的过程也会。

你可能感受到，最近几年 Java 的版本更新速度是很快的，JVM 的参数配置其实变化也很大。就拿 GC 日志这一块来说，Java 9 几乎是推翻重来。网络上的一些文章，把这些参数写的乱七八糟，根本不能投入生产。如果你碰到不能被识别的参数，先确认一下自己的 Java 版本。

面试官：说说你在项目中都使用了哪些打印 GC 日志的参数？

你需要进行总结，比如：

“我一般在项目中输出详细的 GC 日志，并加上可读性强的 GC 日志的时间戳。特别情况下我还会追加一些反映对象晋升情况和堆详细信息的日志，用来排查问题。另外，OOM 时自动 Dump 堆栈，我一般也会进行配置。”

链接：mp.weixin.qq.com/s/Zl_2Ud83K… 作者：李国

更多干货关注公众号 勾勾的Java宇宙（Javagogo)

avatar
文章
阅读
粉丝