背景
上周五业务高峰期,有一个 java 实例毫无征兆的 crash 了,第一时间应用重启之后,将对应的崩溃日志保留,后面做分析。
先说一下该服务的具体情况:
jdk 版本:1.8.0_152-b16
服务器信息:16C32G
启动参数:-Xms18g -Xmx18g -Xss256k -XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=512m -XX:MaxDirectMemorySize=6g -XX:+DisableExplicitGC -XX:+UseG1GC -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=1024k -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=./oom_info.dump -Xloggc:./oom_gcinfo.log -XX:CompressedClassSpaceSize=128m -XX:NativeMemoryTracking=detail
通过启动参数可以看到,使用的是 G1 收集器,且开启了 GC 日志打印。
排查过程
问题分析
由于 jvm 退出时,生成了 hs_err_pidxxx.log 文件,所以直接从该文件分析入手。
打开文件后,主要关注几块信息:
- 文件第一行
这部分会简要的说明崩溃原因 - Problematic frame
崩溃发生的帧所在 - Current thread
崩溃发生时的线程 - siginfo
崩溃信号信息 - Stack
崩溃时的栈详细信息 - Native frames
崩溃时的本地栈帧
在我的场景里,具体的信息为:
#
# A fatal error has been detected by the Java Runtime Environment:
#
# SIGSEGV (0xb) at pc=0x00007efc3752faec, pid=19182, tid=0x00007efbc9279700
#
# JRE version: Java(TM) SE Runtime Environment (8.0_152-b16) (build 1.8.0_152-b16)
# Java VM: Java HotSpot(TM) 64-Bit Server VM (25.152-b16 mixed mode linux-amd64 compressed oops)
# Problematic frame:
# C [libc.so.6+0x85aec] cfree+0x1c
#
# Failed to write core dump. Core dumps have been disabled. To enable core dumping, try "ulimit -c unlimited" before starting Java again
#
# If you would like to submit a bug report, please visit:
# http://bugreport.java.com/bugreport/crash.jsp
#
--------------- T H R E A D ---------------
Current thread (0x00007efc30077000): ConcurrentGCThread [stack: 0x00007efbc917a000,0x00007efbc927a000] [id=19213]
siginfo: si_signo: 11 (SIGSEGV), si_code: 1 (SEGV_MAPERR), si_addr: 0x00007efc37ed0ff8
... 省略很多其他信息 ...
Stack: [0x00007efbc917a000,0x00007efbc927a000], sp=0x00007efbc92788f8, free space=1018k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
C [libc.so.6+0x85aec] cfree+0x1c
在这份报告当中,第一行直接说明了崩溃原因:
SIGSEGV (0xb) at pc=0x00007efc3752faec, pid=19182, tid=0x00007efbc9279700
SIGSEGV (0xb)
表示段错误,通常是由于尝试访问未分配或未映射的内存地址引起的。
而对应的Problematic frame: C [libc.so.6+0x85aec] cfree+0x1c
也说明了这个崩溃是在执行 cfree 时发生的。
到这一步应该有了大概的概念了:jvm 运行时释放了一段未分配或者未映射的内存地址引起的。
但是怎么引起的呢?这个时候就需要通过崩溃发生时的线程Current thread
来确认了,对应的值是:
ConcurrentGCThread
所以到这里,基本上就可以确认,是 G1 收集器的 bug。
问题原因
在官网看了 jdk8 的 release note 之后,找到一个 bug修复记录 JDK-8191393 : Random crashes during cfree+0x1c,里面记载了这个 bug 的修复时间和版本,bug 修复讨论 记录了 bug 产生的原因。
大概原因就是同时启用了 -XX:+UseG1GC 和 -XX:+UseGCLogFileRotation 在打印 gc 日志时的并发问题,有兴趣的同学可以详细看看源码。