最近一段时间生产环境频繁出问题,每次都会生成一个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
          |      |           +-------------------------------- 程序计数器对应的指针
          |      +-------------------------------------------- 信号值(十六进制)
          +--------------------------------------------------- 信号名称
    

    信号名称是操作系统自身的一种信息,CentOS 7下共有以下35种,可在/usr/include/bits/signum.h中查看其具体的声明

    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)]
    

    第一部分展示了引发致命错误的线程,以上为生产的实际信息,因为敏感信息,内容中部分字段使用*进行了脱敏。各部分说明如下:

    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两个版本的文档中并没有相关说明。

    此部分包含线程栈底及栈顶的地址、当前栈指针和未使用的堆栈空间。之后是堆栈帧,最多打印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)
    

    接下来的虚拟机状态主要描述了虚拟机当前的运行状态,包含以下几种:

    虚拟机状态

    互斥锁/管程

    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虚拟机的人有用。持有线程可以在线程列表中找到。

    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 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前后内存使用量未下降的情况,则表示可能出现内存溢出。

    逆向优化事件

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