从一个实战案例入手,分析面对突如其来的GC问题,该如何解决?

面对突如其来的GC,如何下手

Java8 JVM参数

#!/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`
参数意义
OOM时,参数意义

Java13

#!/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前有线程迟迟进入不了safepoint,整个JVM都在等待这个阻塞的线程。
不只是GC会挂起JVM,进入safepoint的过程也会。

如何回答面试官提问项目中使用了哪些参数

“我一般会在项目中输出详细的GC日志,并加上可读性强的GC日志时间戳。特别情况下还会加一些反映对象晋升情况和堆详细信息的日志。另外OOM时自动Dump堆栈。”

GC日志的意义

  1. GC发生的时间
  2. 表明G1的"转移暂停:混合模式",停顿了223ms
  3. 8个worker线程并行执行,消耗了214ms
  4. 表示Diff越小越好,说明每个工作线程的速度都很均匀
  5. 外部根区扫描,外部根区是堆外区。JNI引用,JVM系统目录,ClassLoaders等
  6. 更新RSet时间信息
  7. 该任务主要是对CSet中存活对象进行转移
  8. 花在GC之外的工作线程时间
  9. 并行阶段GC总时间
  10. 其他清理活动
  11. 收集结果统计
  12. 花费时间统计

看到最后一行GC花费时间有三个数值。
在Linux执行time ls /

  • real 实际花费时间,指的是从开始到结束所花费的时间。比如进程等待I/O完成也会被计算在内
  • user 在用户态所花费的时间,只统计本进程所使用的的时间
  • sys 核心态花费的CPU时间,内核中的系统调用所花费的时间。

图中real<user+sys,因为使用多核收集,所以实际时间比(sys+user)少很多,在多核机器上很常见。串行垃圾收集器上面会是=

GC日志可视化

在线分析平台GC Easy
GC 日志文件

jstat命令

jstat -gcutil $pid 1000
jstat每隔1000ms输出

其中,E是eden,S0对应survivor0,S1对应survivor1,O代表Old,M代表Metaspace。
YGC是年轻代回收此时,YGC T中的T是回收耗时,FGC显然就是Full GC。

jstat 的参数

  • gc:显示和GC相关的 堆信息
  • gcutil:显示 垃圾回收信息
  • gccause: 显示垃圾回收信息,同时显示 最后一次或当前正在发生回收的 诱因
  • gcnew:显示新生代信息
  • gccapacity:显示各个代的容量以及使用情况
  • gcmetacapacity:显示元空间大小
  • gcnewcapacity:显示新生代大小和使用情况
  • gcold:显示老年代和永久代的信息
  • gcoldcapacity:显示老年代大小
  • printcompilation:输出JIT编译的方法信息
  • class:显示类加载的相关信息
  • compiler:显示JIT编译相关的信息

下面命令就追加了GC时间的增量和GC时间比率两列

jstat -gcutil -t 90542 1000 | awk 'BEGIN{pre=0}{if(NR>1) {print $0 "\t" ($12-pre) "\t" $12*100/$1 ; pre=$12 } else { print $0 "\tGCT_INC\tRate"} }'
 
Timestamp         S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT    GCT_INC Rate
           18.7   0.00 100.00   6.02   1.45  84.81  76.09      1    0.002     0    0.000    0.002 0.002 0.0106952
           19.7   0.00 100.00   6.02   1.45  84.81  76.09      1    0.002     0    0.000    0.002 0 0.0101523

GC日志也会搞鬼

GC写日志也会算在STW时间里的,如果发生写日志和其他线程争抢I/O时,会导致STW很长。

Last modification:April 3rd, 2020 at 11:54 pm