Java教程

JVM致命错误日志详解

本文主要是介绍JVM致命错误日志详解，对大家解决编程问题具有一定的参考价值，需要的程序猿们随着小编来一起学习吧！

目录
  • 文件描述
  • 文件位置
  • 文件头
    • 错误信息记录
    • JVM运行信息
    • 崩溃原因
    • 错误信息
  • 线程描述
    • 线程信息
    • 信号信息
    • 计数器信息
    • 机器指令
    • 内存映射信息
    • 线程堆栈
    • 其他信息
  • 进程描述
    • 线程列表
    • 虚拟机状态
    • 互斥锁/管程
    • 堆概览
    • 卡表和本地代码缓存
    • 编译事件
    • GC事件
    • 逆向优化事件
    • 内部错误
    • 事件
    • 内存信息
    • 虚拟机参数和环境变量
    • 信号处理器
  • 系统信息
    • 操作系统
    • 内存信息
    • CPU信息
  • 总结

这篇文章是我之前总结的一篇文章，因为整理博客的原因，原有博客已经注销，但这篇文章对一些读者很有用，所以现在新瓶装旧酒重新整理回来分享给大家。

最近一段时间生产环境频繁出问题，每次都会生成一个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问题。

以上是排查过程中发现的问题，本人水平有限，可能问题定位不准确，这份总结仅供各位参考，实际的问题还需要多方面的排查和验证。

这篇关于JVM致命错误日志详解的文章就介绍到这儿，希望我们推荐的文章对大家有所帮助，也希望大家多多支持为之网！
您可能喜欢
栏目导航