JVM致命错误日志详解
这篇文章是我之前总结的一篇文章,因为整理博客的原因,原有博客已经注销,但这篇文章对一些读者很有用,所以现在新瓶装旧酒重新整理回来分享给大家。
最近一段时间生产环境频繁出问题,每次都会生成一个hs_err_pid*.log文件,因为工作内容的原因,在此之前并没有了解过相关内容,趁此机会学习下,根据项目的使用情况,此文章针对JDK 8进行分析,不过因为素材问题,文章中引用的文件内容为JDK 7生成的文件,此处应该不影响,因为官方文档中关于此部分说明使用的是JDK 6生成的文件。我们将按照内容在文件中出现的顺序进行介绍。本人水平有限,工作中也没有太多机会进行此类知识的应用,文章内容主要参考官方文档,某些内容在官方文档中并没有涉及,相应的介绍也不一定准确,如果有不同看法可在评论区留言交流。
PS:本人水平有限,工作中也没有太多机会进行此类知识的应用,文章内容绝大多数来自于官方文档,某些内容在官网中并没有涉及,相应的介绍不一定准确,希望各位大佬不吝赐教
JDK 8
官方文档下载地址:https://www.oracle.com/java/technologies/javase-jdk8-doc-downloads.html
致命错误日志文档:/docs/technotes/guides/troubleshoot/felog.html#fatal_error_log_vm
JDK 7
官方文档地址:https://docs.oracle.com/javase/7/docs/
致命错误日志文档:https://docs.oracle.com/javase/7/docs/webnotes/tsg/TSG-VM/html/felog.html
文件描述
错误日志是在JVM遇到致命错误时生成的日志文件,可能包括以下信息:
- 引发致命错误的异常操作或信号
- 版本和配置信息
- 引发致命错误的线程详细信息和线程堆栈记录
- 正在运行的线程及其状态的列表
- 有关堆的概要信息
- 加载的本机库的列表
- 命令行参数
- 环境变量
- 操作系统和 CPU 的详细信息
当问题严重到错误处理器无法收集并报告所有信息时,可能只有一部分信息会写入错误日志。
文件总共分为一下几个章节:
- 简单描述崩溃信息的文件头
- 线程描述部分
- 进程描述部分
- 系统信息部分
文件位置
致命错误日志文件位置可以通过 -XX:ErrorFile
进行指定,例如:
java * -XX:ErrorFile=/var/log/java/java_error%p.log
以上设置表示文件会放在/var/log/java
目录下,%p
表示进程的PID。如果不设置XX:ErrorFile
属性,日志默认生成在执行java命令的目录下,文件名默认为hs_err_pid%p.log
,如果该目录因为某种情况无法写入(空间不足,权限不足等),在linux系统下默认写到/tmp
目录下,windows系统下默认使用环境变量中TMP
对应的目录,如果没有则使用TEMP
对应的目录(TMP和TEMP均为windows默认的环境变量,且默认值一样)。
文件头
文件头在错误日志的最开头,主要是对问题的简单描述。这部分内容同样会打印到标准输出,可能也会打印到应用程序的控制台上。示例如下:
#
# A fatal error has been detected by the Java Runtime Environment:
#
# SIGSEGV (0xb) at pc=0x00007f80e0cd095c, pid=48, tid=140189843019520
#
# JRE version: Java(TM) SE Runtime Environment (7.0_80-b15) (build 1.7.0_80-b15)
# Java VM: Java HotSpot(TM) 64-Bit Server VM (24.80-b11 mixed mode linux-amd64 compressed oops)
# Problematic frame:
# V [libjvm.so+0x65395c] jni_SetByteArrayRegion+0x19c
#
# Core dump written. Default location: /apps/gateway/project/bin/core or core.48
#
# If you would like to submit a bug report, please visit:
# http://bugreport.java.com/bugreport/crash.jsp
#
错误信息记录
前两行主要描述了信号类型、发起信号的程序计数器、进程ID和线程ID,对应关系如下所示,鉴于浏览器和手机端显示效果不一致,此处提供两种方式:
# SIGSEGV (0xb) at pc=0x00007f80e0cd095c, pid=48, tid=140189843019520
| | | | |
| | | | +--- 线程ID
| | | +----------- 进程ID
| | +-------------------------------- 程序计数器对应的指针
| +-------------------------------------------- 信号值(十六进制)
+--------------------------------------------------- 信号名称
?日志内容 | 实际含义 |
---|---|
SIGSEGV | 信号名称 |
(0xb) | 信号值(十六进制) |
pc=0x00007f80e0cd095c | 程序计数器对应的指针 |
pid=48 | 进程ID |
tid=140189843019520 | 线程ID |
信号名称是操作系统自身的一种信息,CentOS 7下共有以下35种,可在/usr/include/bits/signum.h中查看其具体的声明
信号名称 | 信号值 | 含义 |
---|---|---|
SIGHUP | 1 | Hangup (POSIX). |
SIGINT | 2 | Interrupt (ANSI). |
SIGQUIT | 3 | Quit (POSIX). |
SIGILL | 4 | Illegal instruction (ANSI). |
SIGTRAP | 5 | Trace trap (POSIX). |
SIGABRT | 6 | Abort (ANSI). |
SIGIOT | 6 | IOT trap (4.2 BSD). |
SIGBUS | 7 | BUS error (4.2 BSD). |
SIGFPE | 8 | Floating-point exception (ANSI). |
SIGKILL | 9 | Kill, unblockable (POSIX). |
SIGUSR1 | 10 | User-defined signal 1 (POSIX). |
SIGSEGV | 11 | Segmentation violation (ANSI). |
SIGUSR2 | 12 | User-defined signal 2 (POSIX). |
SIGPIPE | 13 | Broken pipe (POSIX). |
SIGALRM | 14 | Alarm clock (POSIX). |
SIGTERM | 15 | Termination (ANSI). |
SIGSTKFLT | 16 | Stack fault. |
SIGCLD | SIGCHLD | Same as SIGCHLD (System V). |
SIGCHLD | 17 | Child status has changed (POSIX). |
SIGCONT | 18 | Continue (POSIX). |
SIGSTOP | 19 | Stop, unblockable (POSIX). |
SIGTSTP | 20 | Keyboard stop (POSIX). |
SIGTTIN | 21 | Background read from tty (POSIX). |
SIGTTOU | 22 | Background write to tty (POSIX). |
SIGURG | 23 | Urgent condition on socket (4.2 BSD). |
SIGXCPU | 24 | CPU limit exceeded (4.2 BSD). |
SIGXFSZ | 25 | File size limit exceeded (4.2 BSD). |
SIGVTALRM | 26 | Virtual alarm clock (4.2 BSD). |
SIGPROF | 27 | Profiling alarm clock (4.2 BSD). |
SIGWINCH | 28 | Window size change (4.3 BSD, Sun). |
SIGPOLL | SIGIO | Pollable event occurred (System V). |
SIGIO | 29 | I/O now possible (4.2 BSD). |
SIGPWR | 30 | Power failure restart (System V). |
SIGSYS | 31 | Bad system call. |
SIGUNUSED | 31 | - |
JVM运行信息
接下来两行描述了JVM相关版本信息及运行配置信息,内容如下:
# JRE version: Java(TM) SE Runtime Environment (7.0_80-b15) (build 1.7.0_80-b15)
# Java VM: Java HotSpot(TM) 64-Bit Server VM (24.80-b11 mixed mode linux-amd64 compressed oops)
上述文件内容可以得知以下几点:
- JRE版本号为1.7u80
- JVM版本号为24.80-b11
- JVM运行在Server模式下。对应的是Client模式,Client JVM适合需要快速启动和较小内存空间的应用,它适合交互性的应用,比如GUI;而Server JVM则是看重执行效率的应用的最佳选择,更适合服务端应用。
- JVM运行在混合模式下,即mixed mode,是JVM默认的运行模式。其他模式还有解释模式(interpreted mode)和编译模式(compiled mode),解释模式会强制JVM以解释方式执行所有的字节码,编译模式下JVM在第一次使用时会把所有的字节码编译成本地代码,这两种模式各有优劣,单独使用时都会有部分性能上的损失,所以默认使用混合模式即可,混合模式下对于字节码中多次被调用的部分,JVM会将其编译成本地代码以提高执行效率;而被调用很少(甚至只有一次)的方法在解释模式下会继续执行,从而减少编译和优化成本。
崩溃原因
接下来两行描述了引发崩溃问题的函数帧
# Problematic frame:
# V [libjvm.so+0x65395c] jni_SetByteArrayRegion+0x19c
| |
| +-- 类似于程序计数器, 以库名和偏移量表示。
| 对于与位置无关的库(JVM和其他库),可以不通过
| 调试器或通过反汇编程序转存偏移量周围结
| 构的core文件来定位引起崩溃的指令。
+----------------- 帧类型
帧类型包括以下几种:
帧类型 | 描述 |
---|---|
C | Native C frame |
j | Interpreted Java frame |
V | VMframe |
v | VMgenerated stub frame |
J | Other frame types, including compiled Java frames |
关于例子中描述的jni_SetByteArrayRegion+0x19c
这部分目前没有找到相关的资料,官方给的示例中并没有这一部分,根据字面含义来看,此部分应该表示的是崩溃时正在通过JNI方式调用SetByteArrayRegion方法。
错误信息
接下来的错误信息部分根据不同错误显示不一样的内容,在官方给的资料中提供了一份关于内部错误的错误信息,示例如下:
# An unexpected error has been detected by HotSpot Virtual Machine:
# Internal Error (4F533F4C494E55583F491418160E43505000F5), pid=10226, tid=16384
# Java VM: Java HotSpot(TM) Client VM (1.6.0-rc-b63 mixed mode)
以上示例中提供的内容没有信号名称和信号值,只包含了Internal Error
和一个十六进制的字符串,该字符串对出现问题的模块和行号进行了编码,通常情况下只对JVM工程师有用。
因为我们生产环境上出现的问题和示例中的问题种类不一样,所以我们拿到了这样一段信息:
# Core dump written. Default location: /apps/gateway/project/bin/core or core.48
# If you would like to submit a bug report, please visit:
# http://bugreport.java.com/bugreport/crash.jsp
这段信息中记录了core dump文件的位置和官方的BUG反馈页面地址,针对具体问题则需要查看core dump文件了。
线程描述
这一部分描述崩溃时正在运行的线程信息,如果有多个线程同时崩溃,只会打印其中一个线程的信息。
线程信息
Current thread (0x00007f80dc8ce000): JavaThread "RcvThread: com.*.*.*.remote.internal.RemoteTCPConnection[qmid=*,fap=10,peer=/*.*.*.9,localport=*,ssl=no]" daemon [_thread_in_native_trans, id=90,stack(0x00007f807dbb5000,0x00007f807dcb6000)]
第一部分展示了引发致命错误的线程,以上为生产的实际信息,因为敏感信息,内容中部分字段使用*
进行了脱敏。各部分说明如下:
?日志内容 | 实际含义 |
---|---|
(0x0805ac88) | 指针地址 |
JavaThread | 线程类型 |
main | 线程方法名 |
_thread_in_native | 线程状态 |
id=21139 | 线程ID |
stack(0x7dbb5000, 0x7dcb6000) | 栈区间 |
Current thread (0x0805ac88): JavaThread "main" [_thread_in_native, id=21139, stack(0x7dbb5000, 0x7dcb6000)]
| | | | | |
| | | | | +--------- 栈区间
| | | | +---------------------- ID
| | | +--------------------------------- 状态
| | +---------------------------------------------- 名称
| +-------------------------------------------------------- 类型
+---------------------------------------------------------------------- 指针
线程指针指的是JVM内部的线程结构,一般只在实时调试JVM或core文件时才会有用。线程类型包括以下几种:
JavaThread
VMThread
CompilerThread
GCTaskThread
WatcherThread
ConcurrentMarkSweepThread
部分进程可能包含daemon
标识,表示该进程为守护进程,该项不一定会存在。
接下来的线程状态中常见的有以下几种:
Thread State | Description |
---|---|
_thread_uninitialized | 线程未创建,仅在内存崩溃时出现。 |
_thread_new | 线程已被创建,但是没有启动。 |
_thread_in_native | 线程正在执行本地代码,可能因为本地代码的BUG导致此问题。 |
_thread_in_vm | 线程正在执行虚拟机代码。 |
_thread_in_Java | 线程正在执行编译或解释后的Java代码。 |
_thread_blocked | 线程被阻塞。 |
..._trans | 以上状态如果后边带有_trans ,表示线程正在切换状态。 |
信号信息
siginfo:si_signo=SIGSEGV: si_errno=0, si_code=0 (SEGV0), si_addr=0x0000000000000000
信号信息描述了导致JVM终止的异常信号信息,此部分信息根据操作系统不同会有所区别,上边的例子是linux服务器下生成的内容,在windows下内容如下:
siginfo: ExceptionCode=0xc0000005, reading address 0xd8ffecf1
| |
| +--------- 线程异常时读取的地址
+------------------------------------ 异常码
计数器信息
Registers:
RAX=0x00007f80e2109e00, RBX=0x00007f80dc8ce000, RCX=0x0000000000001a70, RDX=0x00007f80e14c87f0
RSP=0x00007f807dca4710, RBP=0x00007f807dca4780, RSI=0x00007f807dcb47f8, RDI=0x00007f80dc8ce1e8
R8 =0x00007f807dca47a0, R9 =0x000000000000005a, R10=0x0000000000000000, R11=0x0000000000000000
R12=0x00007f807dcb47f8, R13=0x0000000000001a70, R14=0x0000000000000000, R15=0x00007f80e14c8800
RIP=0x00007f80e0cd095c, EFLAGS=0x0000000000010206, CSGSFS=0xffff000000000033, ERR=0x0000000000000007
TRAPNO=0x000000000000000e
此部分内容为程序崩溃时程序计数器中的内容,这一部分的打印格式和服务器的处理器类型有关,以上为我手中文件的内容,这一部分内容与下一部分结合来看会比较有用(实际上也没看懂)。
机器指令
Top of Stack: (sp=0x00007f807dca4710)
0x00007f807dca4710: 0000000000007ffe 00007f807dca47a0
0x00007f807dca4720: 00007f807dcb5700 00007f807dcb5680
......
0x00007f807dca48f0: 2020202020202020 2020202020202020
0x00007f807dca4900: 2020202020202020 1c00000020202020
Instructions: (pc=0x00007f80e0cd095c)
0x00007f80e0cd093c: ff 0f 1f 00 48 8b 05 59 b3 7b 00 48 89 da 48 c1
0x00007f80e0cd094c: ea 04 8b 00 21 d0 48 8b 15 cf 6f 7b 00 48 03 02
0x00007f80e0cd095c: c7 00 01 00 00 00 e9 b6 fe ff ff 66 0f 1f 84 00
0x00007f80e0cd096c: 00 00 00 00 45 85 ed 74 40 84 c9 74 77 48 8b 05
以上是博主文件的内容,因为篇幅原因中间部分隐藏了,这一部分内容包含了系统崩溃时程序计数器栈顶的32个指令。这些信息可以通过反编译程序编译出崩溃地址附近的指令。需要注意的是A32和AMD64架构的指令长度不一致,所以并不一定能够反编译出这部分指令。
内存映射信息
Register to memory mapping:
RAX=0x00007f80e2109e00 is an unknown value
RBX=0x00007f80dc8ce000 is a thread
RCX=0x0000000000001a70 is an unknown value
RDX=0x00007f80e14c87f0: <offset 0xe4b7f0> in /usr/java/jdk1.7.0_80/jre/lib/amd64/server/libjvm.so at 0x00007f80e067d000
RSP=0x00007f807dca4710 is pointing into the stack for thread: 0x00007f80dc8ce000
RBP=0x00007f807dca4780 is pointing into the stack for thread: 0x00007f80dc8ce000
RSI=0x00007f807dcb47f8 is pointing into the stack for thread: 0x00007f80dc8ce000
RDI=0x00007f80dc8ce1e8 is an unknown value
R8 =0x00007f807dca47a0 is pointing into the stack for thread: 0x00007f80dc8ce000
R9 =0x000000000000005a is an unknown value
R10=0x0000000000000000 is an unknown value
R11=0x0000000000000000 is an unknown value
R12=0x00007f807dcb47f8 is pointing into the stack for thread: 0x00007f80dc8ce000
R13=0x0000000000001a70 is an unknown value
R14=0x0000000000000000 is an unknown value
R15=0x00007f80e14c8800: <offset 0xe4b800> in /usr/java/jdk1.7.0_80/jre/lib/amd64/server/libjvm.so at 0x00007f80e067d000
此部分信息在博主的文件中存在,但在JDK 7和8两个版本的文档中并没有相关说明。但根据RAX
、RBX
等内容推测是崩溃时CPU各个寄存器中所保存的内容。
线程堆栈
此部分包含线程栈底及栈顶的地址、当前栈指针和未使用的堆栈空间。之后是堆栈帧,最多打印100帧。对于C/C++架构,可能库名也会被打印。
当出现某些致命错误信息时,可能堆栈已经损坏,在这种情况下,这部分信息不可用。
Stack: [0x00007f807dbb5000,0x00007f807dcb6000], sp=0x00007f807dca4710, free space=957k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V [libjvm.so+0x65395c] jni_SetByteArrayRegion+0x19c
Java frames: (J=compiled Java code, j=interpreted, Vv=VM code)
J 1342 java.net.SocketInputStream.socketRead0(Ljava/io/FileDescriptor;[BIII)I (0 bytes) @ 0x00007f80d8bdc0c7 [0x00007f80d8bdc060+0x67]
J 1341 C2 java.net.SocketInputStream.read([BIII)I (567 bytes) @ 0x00007f80d8bfcc90 [0x00007f80d8bfcb00+0x190]
J 1258 C2 com.*.*.*.remote.internal.RemoteTCPConnection.receive([BII)I (775 bytes) @ 0x00007f80d8b87fc0 [0x00007f80d8b87f20+0xa0]
J 1346 C2 com.*.*.*.remote.internal.RemoteRcvThread.receiveBuffer()I (400 bytes) @ 0x00007f80d8c05630 [0x00007f80d8c05580+0xb0]
J 1032 C2 com.*.*.*.remote.internal.RemoteRcvThread.receiveOneTSH()Lcom/*/*/*/remote/internal/system/RfpTSH; (338 bytes) @ 0x00007f80d89dc354 [0x00007f80d89dc120+0x234]
J 1363% C2 com.*.*.*.remote.internal.RemoteRcvThread.run()V (2498 bytes) @ 0x00007f80d8c119b8 [0x00007f80d8c11760+0x258]
j java.lang.Thread.run()V+11
v ~StubRoutines::call_stub
以上日志内容包含两个线程堆栈:
- 第一部分堆栈是
Native frames
,打印了本地线程所有的方法调用。然而内联方法作为上级堆栈的一部分,线程堆栈不会考虑运行时编译器内联的Java方法。本地帧的线程堆栈信息提供关于崩溃的重要信息。通过自上而下分析列表中的库,一般可以确定引起问题的库并报告给对应的组织。 - 第二部分堆栈是跳过本地帧打印了内联方法的Java帧,根据崩溃情况可能不会打印本地帧,但大概率会打印Java帧。
其他信息
如果错误发生在VM线程或编译器线程,后边的例子中会显示更多信息。例如,问题出现在VM线程中,崩溃时VM线程正在执行的操作将会被打印下来。下面的例子展示了编译器线程引起崩溃,执行的内容是编译器正在编译方法hs101t004Thread.ackermann
。因为出现的问题不一致,这部分内容并没有出现在博主的文件中。对于HotSpot虚拟机来说这部分文件可能稍微的有点不同,但都会包含完整的类名和方法名。
Current CompileTask:
HotSpot Client Compiler:754 b
nsk.jvmti.scenarios.hotswap.HS101.hs101t004Thread.ackermann(IJ)J (42 bytes)
进程描述
进程相关内容在线程之后打印,主要包含整个进程的线程列表和内存使用情况。
线程列表
Java Threads: ( => current thread )
0x00007f80dc75b000 JavaThread "Thread-12" [_thread_blocked, id=93, stack(0x00007f807d8b2000,0x00007f807d9b3000)]
0x00007f80dc75a000 JavaThread "Thread-11" [_thread_blocked, id=92, stack(0x00007f807d9b3000,0x00007f807dab4000)]
0x00007f80dc759800 JavaThread "Thread-10" [_thread_blocked, id=91, stack(0x00007f807dab4000,0x00007f807dbb5000)]
=>0x00007f80dc8ce000 JavaThread "RcvThread: com.*.*.*.remote.internal.RemoteTCPConnection[qmid=*,fap=10,peer=/*,localport=*,ssl=no]" daemon [_thread_in_native_trans, id=90, stack(0x00007f807dbb5000,0x00007f807dcb6000)]
0x00007f80dc636800 JavaThread "WebSphere MQ Trace Monitor" daemon [_thread_blocked, id=89, stack(0x00007f807dcb6000,0x00007f807ddb7000)]
......
Other Threads:
0x00007f80dc093800 VMThread [stack: 0x00007f807f5f6000,0x00007f807f6f7000] [id=73]
0x00007f80dc0d5000 WatcherThread [stack: 0x00007f807eeef000,0x00007f807eff0000] [id=80]
以上内容为博主手中日志文件的内容,因为篇幅问题部分内容被省略。此部分线程列表中主要是VM已知的线程,包括Java线程和VM内部的线程。Other Threads
部分主要包含用户程序创建但没有包含在VM内部的本地线程。
关于线程的描述与本文之前介绍的线程部分一致。
虚拟机状态
VM state:synchronizing (normal execution)
接下来的虚拟机状态主要描述了虚拟机当前的运行状态,包含以下几种:
虚拟机状态 | 描述 |
---|---|
not at a safepoint | 正常执行 |
at safepoint | 虚拟机中所有线程均被阻塞,等待特殊的虚拟机操作完成 |
synchronizing | 一个特殊的虚拟机操作,需要等待虚拟机中所有的线程处于阻塞状态 |
互斥锁/管程
VM Mutex/Monitor currently owned by a thread: ([mutex/lock_event])
[0x00007f80dc006060] Safepoint_lock - owner thread: 0x00007f80dc093800
[0x00007f80dc0060e0] Threads_lock - owner thread: 0x00007f80dc093800
[0x00007f80dc0065e0] Heap_lock - owner thread: 0x00007f80dc5a7800
此部分描述了当前线程持有的互斥锁和管程。如上例所示,这些是虚拟机内部的互斥锁,不是Java对象关联的管程。它展示了程序崩溃发生时虚拟机持有锁的情况,包含了锁名称、持有者和虚拟机内部互斥锁的地址。通常情况下此部分只对非常熟悉HotSpot虚拟机的人有用。持有线程可以在线程列表中找到。
堆概览
Heap
PSYoungGen total 1397248K, used 1396672K [0x0000000755500000, 0x00000007aaa80000, 0x0000000800000000)
eden space 1396224K, 100% used [0x0000000755500000,0x00000007aa880000,0x00000007aa880000)
from space 1024K, 43% used [0x00000007aa880000,0x00000007aa8f0000,0x00000007aa980000)
to space 1024K, 0% used [0x00000007aa980000,0x00000007aa980000,0x00000007aaa80000)
ParOldGen total 2796544K, used 14720K [0x0000000600000000, 0x00000006aab00000, 0x0000000755500000)
object space 2796544K, 0% used [0x0000000600000000,0x0000000600e60318,0x00000006aab00000)
PSPermGen total 21504K, used 18411K [0x00000005fae00000, 0x00000005fc300000, 0x0000000600000000)
object space 21504K, 85% used [0x00000005fae00000,0x00000005fbffada0,0x00000005fc300000)
此部分内容主要为堆内存概览,输出内容取决于使用的垃圾回收器,以上内容使用的是JDK 7默认的组合(Parallel Scavenge+Parallel Old)。以上内容中比较奇怪的一点是,我们的项目运行了有一段时间了,结果老年代空间使用率约等于0%,此部分需要排查代码,另外一点是新生代的使用率达到100%,说明崩溃时可能是在对新生代进行GC。
卡表和本地代码缓存
Card table byte_map: [0x00007f80d7772000,0x00007f80d879c000] byte_map_base: 0x00007f80d479b000
Code Cache [0x00007f80d879c000, 0x00007f80d8f4c000, 0x00007f80db79c000)
total_blobs=2892 nmethods=2508 adapters=338 free_code_cache=41446Kb largest_free_block=42334144
此部分内容在官方文档中没有进行介绍,通过查看其他资料得知,卡表是JVM维护的一种数据结构,用于记录更改对象时的引用,以便提高GC效率,本地代码缓存主要用于编译和保存本地代码。
此部分具体的用处存疑,希望有了解的大佬可以赐教。
编译事件
Compilation events (10 events):
Event: 83314.233 Thread 0x00007f80dc0c8000 nmethod 2661 0x00007f80d8f2f590 code [0x00007f80d8f2f800, 0x00007f80d8f2fd98]
Event: 83314.235 Thread 0x00007f80dc0c8000 2662 ! bsh.Parser::AndExpression (232 bytes)
Event: 83314.235 Thread 0x00007f80dc0c5000 nmethod 2660 0x00007f80d8f363d0 code [0x00007f80d8f366e0, 0x00007f80d8f36f68]
Event: 83314.246 Thread 0x00007f80dc0c8000 nmethod 2662 0x00007f80d8f2eb50 code [0x00007f80d8f2ed40, 0x00007f80d8f2f0a0]
Event: 83499.918 Thread 0x00007f80dc0c5000 2663 java.math.BigDecimal$StringBuilderHelper::putIntCompact (197 bytes)
Event: 83499.930 Thread 0x00007f80dc0c5000 nmethod 2663 0x00007f80d8f2c750 code [0x00007f80d8f2c8c0, 0x00007f80d8f2cf98]
Event: 84638.783 Thread 0x00007f80dc0c8000 2664 java.util.AbstractList::hashCode (46 bytes)
Event: 84638.841 Thread 0x00007f80dc0c8000 nmethod 2664 0x00007f80d8f39f90 code [0x00007f80d8f3a100, 0x00007f80d8f3a378]
Event: 85085.178 Thread 0x00007f80dc0c5000 2665 sun.nio.ch.EPollSelectorImpl::updateSelectedKeys (150 bytes)
Event: 85085.233 Thread 0x00007f80dc0c5000 nmethod 2665 0x00007f80d8f38590 code [0x00007f80d8f387c0, 0x00007f80d8f39248]
此部分内容在官方文档中未进行介绍,不过根据内容来看,此部分包含了程序崩溃前执行的十次编译任务。
GC事件
GC Heap History (10 events):
Event: 84610.584 GC heap before
{Heap before GC invocations=309 (full 0):
PSYoungGen total 1397248K, used 1396764K [0x0000000755500000, 0x00000007aaa80000, 0x0000000800000000)
eden space 1396224K, 100% used [0x0000000755500000,0x00000007aa880000,0x00000007aa880000)
from space 1024K, 52% used [0x00000007aa980000,0x00000007aaa071b8,0x00000007aaa80000)
to space 1024K, 0% used [0x00000007aa880000,0x00000007aa880000,0x00000007aa980000)
ParOldGen total 2796544K, used 14686K [0x0000000600000000, 0x00000006aab00000, 0x0000000755500000)
object space 2796544K, 0% used [0x0000000600000000,0x0000000600e57bd8,0x00000006aab00000)
PSPermGen total 21504K, used 18408K [0x00000005fae00000, 0x00000005fc300000, 0x0000000600000000)
object space 21504K, 85% used [0x00000005fae00000,0x00000005fbffa340,0x00000005fc300000)
Event: 84610.588 GC heap after
Heap after GC invocations=309 (full 0):
PSYoungGen total 1397248K, used 320K [0x0000000755500000, 0x00000007aaa80000, 0x0000000800000000)
eden space 1396224K, 0% used [0x0000000755500000,0x0000000755500000,0x00000007aa880000)
from space 1024K, 31% used [0x00000007aa880000,0x00000007aa8d0000,0x00000007aa980000)
to space 1024K, 0% used [0x00000007aa980000,0x00000007aa980000,0x00000007aaa80000)
ParOldGen total 2796544K, used 14686K [0x0000000600000000, 0x00000006aab00000, 0x0000000755500000)
object space 2796544K, 0% used [0x0000000600000000,0x0000000600e57bd8,0x00000006aab00000)
PSPermGen total 21504K, used 18408K [0x00000005fae00000, 0x00000005fc300000, 0x0000000600000000)
object space 21504K, 85% used [0x00000005fae00000,0x00000005fbffa340,0x00000005fc300000)
}
......
此部分内容同样在官方文档中没有说明,但是了解JVM垃圾回收的应该都可以看懂,因为篇幅问题只展示前两段。以下对内容进行简要说明:
Event: 84610.584 GC heap before
|
+------垃圾回收发生的时间,单位秒,从JVM启动开始计时
Heap before GC invocations=309 (full 0):
| |
| +------此前Full GC发生的次数
+---------------当前GC次数(此处代表第309次GC)
其他部分表示JVM内存各个分区在GC前后的使用情况,如果出现GC后相较于GC前内存使用量未下降的情况,则表示可能出现内存溢出。
逆向优化事件
Deoptimization events (10 events):
Event: 62518.966 Thread 0x00007f80dc5a7800 Uncommon trap: reason=unstable_if action=reinterpret pc=0x00007f80d8f1cea4 method=bsh.NameSpace.getClass(Ljava/lang/String;)Ljava/lang/Class; @ 16
Event: 65561.299 Thread 0x00007f801400c000 Uncommon trap: reason=unstable_if action=reinterpret pc=0x00007f80d8d46158 method=sun.nio.ch.Util$BufferCache.get(I)Ljava/nio/ByteBuffer; @ 26
Event: 67079.495 Thread 0x00007f801400c000 Uncommon trap: reason=unstable_if action=reinterpret pc=0x00007f80d8cad61c method=sun.nio.ch.Util$BufferCache.get(I)Ljava/nio/ByteBuffer; @ 26
Event: 67175.303 Thread 0x00007f80dc8ce000 Uncommon trap: reason=unstable_if action=reinterpret pc=0x00007f80d8e80c44 method=com.*.*.*.remote.internal.system.RemoteProxyQueue.addMessage(Lcom/*/*/*/remote/internal/system/RemoteTls;Lcom/*/*/*/remote/internal/system/RfpTSH;Lcom/*/
Event: 67175.364 Thread 0x00007f801400c000 Uncommon trap: reason=unstable_if action=reinterpret pc=0x00007f80d8c7c650 method=sun.nio.ch.Util$BufferCache.get(I)Ljava/nio/ByteBuffer; @ 26
Event: 70454.736 Thread 0x00007f80dc5b7000 Uncommon trap: reason=unstable_if action=reinterpret pc=0x00007f80d8b23004 method=java.lang.Long.getChars(JI[C)V @ 24
Event: 70650.379 Thread 0x00007f80dc5ad000 Uncommon trap: reason=unstable_if action=reinterpret pc=0x00007f80d8e0f700 method=java.util.ArrayDeque.pollFirst()Ljava/lang/Object; @ 13
Event: 76653.752 Thread 0x00007f80dc09a000 Uncommon trap: reason=bimorphic action=maybe_recompile pc=0x00007f80d8d837b4 method=java.lang.System$2.invokeFinalize(Ljava/lang/Object;)V @ 1
Event: 84618.642 Thread 0x00007f801400c000 Uncommon trap: reason=unstable_if action=reinterpret pc=0x00007f80d8eef598 method=sun.nio.ch.SocketChannelImpl.translateReadyOps(IILsun/nio/ch/SelectionKeyImpl;)Z @ 140
Event: 84618.654 Thread 0x00007f801400c000 Uncommon trap: reason=unstable_if action=reinterpret pc=0x00007f80d8b00478 method=sun.nio.ch.EPollSelectorImpl.updateSelectedKeys()I @ 124
JVM会在运行过程中对代码进行编译优化,过程中包含一部分不稳定的激进优化,当激进优化不成立时会通过逆向优化退回到解释状态进行执行,此部分就是介绍的崩溃前的十次逆向优化内容,这部分内容在官方文档中并没有详细说明。
内部错误
Internal exceptions (10 events):
Event: 85322.248 Thread 0x00007f80dc5ad000 Threw 0x00000007a5d71078 at /HUDSON/workspace/7u-2-build-linux-amd64/jdk7u80/2329/hotspot/src/share/vm/prims/jvm.cpp:1319
Event: 85322.249 Thread 0x00007f80dc5ad000 Threw 0x00000007a5d986f8 at /HUDSON/workspace/7u-2-build-linux-amd64/jdk7u80/2329/hotspot/src/share/vm/prims/jvm.cpp:1319
Event: 85322.249 Thread 0x00007f80dc5ad000 Threw 0x00000007a5d98a20 at /HUDSON/workspace/7u-2-build-linux-amd64/jdk7u80/2329/hotspot/src/share/vm/prims/jvm.cpp:1319
Event: 85322.249 Thread 0x00007f80dc5ad000 Threw 0x00000007a5d9b088 at /HUDSON/workspace/7u-2-build-linux-amd64/jdk7u80/2329/hotspot/src/share/vm/prims/jvm.cpp:1319
Event: 85322.738 Thread 0x00007f80dc5a8800 Threw 0x00000007a92c18f8 at /HUDSON/workspace/7u-2-build-linux-amd64/jdk7u80/2329/hotspot/src/share/vm/prims/jvm.cpp:1319
Event: 85322.738 Thread 0x00007f80dc5a8800 Threw 0x00000007a92c1c20 at /HUDSON/workspace/7u-2-build-linux-amd64/jdk7u80/2329/hotspot/src/share/vm/prims/jvm.cpp:1319
Event: 85322.738 Thread 0x00007f80dc5a8800 Threw 0x00000007a92c4288 at /HUDSON/workspace/7u-2-build-linux-amd64/jdk7u80/2329/hotspot/src/share/vm/prims/jvm.cpp:1319
Event: 85322.741 Thread 0x00007f80dc5b7000 Threw 0x00000007a982b580 at /HUDSON/workspace/7u-2-build-linux-amd64/jdk7u80/2329/hotspot/src/share/vm/prims/jvm.cpp:1319
Event: 85322.741 Thread 0x00007f80dc5b7000 Threw 0x00000007a982b8a8 at /HUDSON/workspace/7u-2-build-linux-amd64/jdk7u80/2329/hotspot/src/share/vm/prims/jvm.cpp:1319
Event: 85322.742 Thread 0x00007f80dc5b7000 Threw 0x00000007a982df10 at /HUDSON/workspace/7u-2-build-linux-amd64/jdk7u80/2329/hotspot/src/share/vm/prims/jvm.cpp:1319
此部分在官方文档中并没有进行说明,且当前文件中的内容可阅读的信息较少,在查阅相关资料过程中发现部分错误此处可能打印具体的异常信息。当前文件中可以看出在0.5s内发生了10次内部错误,综合文件其他地方的时间来看,这个时间点很接近崩溃发生的时间,且与最后一次未发生的GC时间基本相符。
事件
Events (10 events):
Event: 85322.248 loading class 0x00007f80dc52a460 done
Event: 85322.248 loading class 0x00007f80dc52a460
Event: 85322.248 loading class 0x00007f80dc52a460 done
Event: 85322.249 loading class 0x00007f80dc52a460
Event: 85322.249 loading class 0x00007f80dc52a460 done
Event: 85322.738 loading class 0x00007f80dc52a460
Event: 85322.738 loading class 0x00007f80dc52a460 done
Event: 85322.741 loading class 0x00007f80dc52a460
Event: 85322.741 loading class 0x00007f80dc52a460 done
Event: 85322.742 Executing VM operation: ParallelGCFailedAllocation
此部分在官方文档中并没有进行说明,此部分主要包含JVM在崩溃前的十次操作事件,以上内容可以看出最后一次事件为ParallelGCFailedAllocation,在网上没有查到这个操作的资料,根据字面含义为执行Parallel垃圾回收器回收失败后的再分配过程,此处的疑点是在崩溃前新生代内存使用率已经是100%了,可能是这个事件导致的内存溢出。
内存信息
Dynamic libraries:
00400000-00401000 r-xp 00000000 fd:01 268667146 /usr/java/jdk1.7.0_80/bin/java
00600000-00601000 rw-p 00000000 fd:01 268667146 /usr/java/jdk1.7.0_80/bin/java
01097000-010b8000 rw-p 00000000 00:00 0 [heap]
......
7f80e210c000-7f80e210d000 r--p 0001f000 fd:01 302335055 /usr/lib64/ld-2.17.so
7f80e210d000-7f80e210e000 rw-p 00020000 fd:01 302335055 /usr/lib64/ld-2.17.so
7f80e210e000-7f80e210f000 rw-p 00000000 00:00 0
7fff254c6000-7fff254e7000 rw-p 00000000 00:00 0 [stack]
7fff25514000-7fff25516000 r-xp 00000000 00:00 0 [vdso]
ffffffffff600000-ffffffffff601000 r-xp 00000000 00:00 0 [vsyscall]
此部分信息展示了崩溃时的内存信息,这个列表在比较大的应用程序中可能会比较长,博主的文件中这一部分不算空行占了350多行。此部分在调试崩溃情况时非常有用,可以描述被使用的库及其使用的内存地址,以及堆、栈和保护单元的地址。
此部分内容的格式与操作系统相关,以上例子为Linux下的格式,以下是对内容的简单介绍:
?日志内容 | 实际含义 |
---|---|
00400000-00401000 | 内存区域 |
r-xp | 权限(r:读取、w:写入、x:执行、p:私有、s:共享) |
00000000 | 文件偏移量 |
fd:01 | 文件所在设备的主要和次要ID |
268667146 | 索引编号 |
/usr/java/jdk1.7.0_80/bin/java | 文件名 |
00400000-00401000 r-xp 00000000 fd:01 268667146 /usr/java/jdk1.7.0_80/bin/java
|<------------->| ^ ^ ^ ^ |<- -------------------------->|
| | | | | |
| | | | | +------------------- 文件名
| | | | +------------------------------------------- 索引编号
| | | +------------------------------------------------- 文件所在设备的主要和次要ID
| | +--------------------------------------------------------- 文件偏移量
| +---------------------------------------------------------------- 权限(r:读取、w:写入、x:执行、p:私有、s:共享)
+--------------------------------------------------------------------------- 内存区域
虚拟机参数和环境变量
VM Arguments:
jvm_args: -Dfile.encoding=UTF8 -Dsun.jnu.encoding=UTF8 -Xms4096m -Xmx8192m
java_command: com.giantstone.commgateway.startup.Bootstrap ../../gateway-comm-lib/lib ../config ../deploy front_core start
Launcher Type: SUN_STANDARD
Environment Variables:
PATH=/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin:/root/bin
SHELL=/bin/bash
此部分应该是最简单易懂的,描述的是和Java虚拟机有关的环境变量及其自身运行时使用的参数。
信号处理器
Signal Handlers:
SIGSEGV: [libjvm.so+0x9a3b20], sa_mask[0]=0x7ffbfeff, sa_flags=0x10000004
SIGBUS: [libjvm.so+0x9a3b20], sa_mask[0]=0x7ffbfeff, sa_flags=0x10000004
SIGFPE: [libjvm.so+0x81e740], sa_mask[0]=0x7ffbfeff, sa_flags=0x10000004
SIGXFSZ: [libjvm.so+0x81e740], sa_mask[0]=0x7ffbfeff, sa_flags=0x10000004
SIGILL: [libjvm.so+0x81e740], sa_mask[0]=0x7ffbfeff, sa_flags=0x10000004
SIGUSR1: SIG_DFL, sa_mask[0]=0x00000000, sa_flags=0x00000000
SIGUSR2: [libjvm.so+0x81ffb0], sa_mask[0]=0x00000000, sa_flags=0x10000004
SIGHUP: SIG_IGN, sa_mask[0]=0x00000000, sa_flags=0x00000000
SIGINT: SIG_IGN, sa_mask[0]=0x00000000, sa_flags=0x00000000
SIGTERM: [libjvm.so+0x8210d0], sa_mask[0]=0x7ffbfeff, sa_flags=0x10000004
SIGQUIT: [libjvm.so+0x8210d0], sa_mask[0]=0x7ffbfeff, sa_flags=0x10000004
此部分内容为Linux特有的内容,主要描述针对信号所使用的处理程序。
系统信息
日志最后一大部分是操作系统相关的内容,也是整个文件当中最直观的部分,主要包含操作系统版本、CPU信息和内存概要。
操作系统
OS:Red Hat Enterprise Linux Server release 7.0 (Maipo)
uname:Linux 3.10.0-514.el7.x86_64 #1 SMP Wed Oct 19 11:24:13 EDT 2016 x86_64
libc:glibc 2.17 NPTL 2.17
rlimit: STACK 8192k, CORE infinity, NPROC infinity, NOFILE 65536, AS infinity
load average:6.02 5.99 5.89
此部分内容为针对操作系统的基本信息和运行中的平均负载情况。
内存信息
Memory: 4k page, physical 131862044k(14543760k free), swap 33554428k(33531212k free)
/proc/meminfo:
MemTotal: 131862044 kB
MemFree: 14543760 kB
MemAvailable: 120724836 kB
Buffers: 1584 kB
Cached: 107254088 kB
......
HugePages_Surp: 0
Hugepagesize: 2048 kB
DirectMap4k: 378736 kB
DirectMap2M: 133838848 kB
内存部分在文件中实际分了两部分,这里我们放在一起展示,因为篇幅原因内存详情只展示开头和结尾的部分,这部分主要包含系统运行时的内存使用情况,这里有个问题,我们的应用跑在容器之中,分配的容器内存只有8G,但这里获取到的内存则是整台宿主机的内存。
CPU信息
CPU:total 32 (1 cores per cpu, 1 threads per core) family 6 model 6 stepping 3, cmov, cx8, fxsr, mmx, sse, sse2, sse3, tsc
/proc/cpuinfo:
# 此处省略掉每个CPU核心的描述信息
CPU信息部分包括概览以及对每个核心的描述,因为篇幅原因省略掉了,此处和内存存在同样的问题,容器内的应用获取到了宿主机的CPU信息。
总结
通过查询相关资料,对JVM致命错误日志内容有了初步的了解,在学习的过程中发现了以下几个疑点:
- 崩溃时正在通过JNI方式调用SetByteArrayRegion这个方法进行数组处理,通过堆栈信息可以看到是在调用RemoteTCPConnection.receive()时报的错,而这个类是我们引用的MQ中的方法,后续需要对相关的代码进行排查,确定使用的版本是否正常,相关代码是否存在问题。
- 在查看堆内存和事件部分可以得知,在崩溃时内存中新生代的使用率已经达到了100%,在事件中也触发了ParallelGCFailedAllocation,考虑是不是因为在调用RemoteTCPConnection.receive()时出现了内存溢出问题。
- 容器内的应用在获取硬件信息时获取到了宿主机的硬件信息,这个地方会有一个隐患,java默认使用物理内存的一半来作为虚拟机的内存,如果说在使用java时没有手动设定
Xmx
参数,也就意味着该进程使用的内存可能会远大于容器的内存。此份日志文件中可以看到设置的-Xmx=8192m
,但实际我们给容器分配的内存也是8G,而另外的应用中使用的Tomcat并没有设置此参数。 - 在排查问题时还发现JDK 7本身与容器存在兼容性问题,网上的资料建议使用JDK 8u131以后的版本,但是博主未在JDK 8u131的更新日志中发现相关内容,倒是在8u191的更新日志中找到了,目前计划将JDK更新至8u201,同时使用G1垃圾回收器,验证能不能解决之前出现的GC问题。
以上是排查过程中发现的问题,本人水平有限,可能问题定位不准确,这份总结仅供各位参考,实际的问题还需要多方面的排查和验证。