JVM致命错误日志(hs_err_pid.log)分析

22 0 0

概览

当jvm出现致命错误时，会生成一个错误文件 hs_err_pid.log，其中包括了导致jvm crash的重要信息，可以通过分析该文件定位到导致crash的根源，从而改善以保证系统稳定。

当出现crash时，该文件默认会生成到工作目录下，然而可以通过jvm参数指定生成路径（JDK6中引入）：-XX:ErrorFile=./hs_err_pid.log
该文件包含如下几类关键信息：

日志头文件
导致crash的线程信息
所有线程信息
安全点和锁信息
堆信息
本地代码缓存
编译事件
gc相关记录
jvm内存映射
jvm启动参数
服务器信息

日志头信息

日志头文件包含概要信息，简述了导致crash的原因。而导致crash的原因很多，常见的原因有jvm自身的bug，应用程序错误，jvm参数配置不当，服务器资源不足，jni调用错误等。
示例：

# There is insufficient（不足） memory for the Java Runtime Environment to continue.
# Native memory allocation (mmap) failed to map 398 458 880 bytes for committing reserved（保留，预留） memory.
# Possible reasons:
#   The system is out of physical RAM or swap space
#   In 32 bit mode, the process size limit was hit
# Possible solutions:
#   Reduce memory load on the system
#   Increase physical memory or swap space
#   Check if swap backing store is full
#   Use 64 bit Java on a 64 bit OS
#   Decrease Java heap size (-Xmx/-Xms)
#   Decrease number of Java threads
#   Decrease Java thread stack sizes (-Xss)
#   Set larger code cache with -XX:ReservedCodeCacheSize=
# This output file may be truncated or incomplete.
#
#  Out of Memory Error (os_linux.cpp:2716), pid=77665, tid=140321575270144
#
# JRE version:  (8.0_11-b12) (build )
# Java VM: Java HotSpot(TM) 64-Bit Server VM (25.11-b03 mixed mode linux-amd64 compressed oops)
# Failed to write core dump. Core dumps have been disabled. To enable core dumping, try "ulimit -c unlimited" before starting Java again

可能的问题原因：
1.内存不够
查看内存 free -h 或 cat /proc/meminfo
2.进程打开数达到上限
可以通过ulimit -a来查看当前Linux系统的一些系统参数,其中max user processes是系统允许创建的最大进程数，open files是一个进程可打开的最大文件数。

# ulimit -a 命令（列出所有当前资源极限）的输出信息（其他命令可参考输出信息中括号内的提示）: 
core file size        (blocks, -c) 0
data seg size         (kbytes, -d) unlimited  # 一个进程的数据段的最大值
scheduling priority   (-e) 0
file size             (blocks, -f) unlimited  # Shell创建文件的最大体积, 1block = 512bytes
pending signals       (-i) 1031426    # 最多允许多少个待处理的信号
max locked memory     (kbytes, -l) 64         # 每个进程可以锁住的物理内存的最大值
max memory size       (kbytes, -m) unlimited  # 每个进程可以使用的常驻内存的最大值
open files            (-n) 65535      # 每个进程可以同时打开的最大文件数, 不能是unlimited
pipe size             (512 bytes, -p) 8       # 管道的最大值, 1block = 512bytes
POSIX message queues  (bytes, -q) 819200      # POSIX的消息队列的最大值
real-time priority    (-r) 0
stack size            (kbytes, -s) 10240      # 单个进程能够使用的最大栈大小
cpu time              (seconds, -t) unlimited # 单个进程的最大CPU时间, 也就是可使用CPU的秒数, 到硬极限时, 这个进程就会立即自杀; 到软极限时, 每秒发送一次限制超时信号SIGXCPU
max user processes    (-u) 131072            #单个用户可同时运行的最大进程数, 不能是unlimited
virtual memory        (kbytes, -v) unlimited  # 每个进程可使用的最大虚拟内存
file locks            (-x) unlimited          # 每个进程能锁住的最大文件个数

对max user processes的配置, Linux系统默认先读取/etc/security/limits.conf 中的信息, 如果/etc/security/limits.d/目录下还有配置文件的话, 也会依次遍历读取, 最终, /etc/security/limits.d/中的配置会覆盖/etc/security/limits.conf 中的配置

修改/etc/security/limits.conf文件, 在文件最后添加下述内容
# nproc 用户进程数的默认限制
*  soft      nproc      131072
*  hard      nproc      131072

另外，Linux 系统默认的max open files = 1024, 在大内存服务器中, 如果运行负载比较大的程序, 很容易发生error: too many open files, 特别是提供大量静态文件访问的Web服务器、缓存服务器中这种错误更加常见.

在/etc/security/limits.conf最后增加如下两行记录
# nofile - 可以打开的最大文件数, *通配符表示对所有用户有效
*   soft      nofile     65535
*   hard      nofile     65535

注意：max open files和max user processes是不能配置unlimited的 —— 极不安全的设置, 此时系统会使用默认的配置值。

导致crash的线程信息

---------------  T H R E A D  ---------------
Current thread (0x00007f9f20009000):  JavaThread "Unknown thread" [_thread_in_vm, id=77666, stack(0x00007f9f29960000,0x00007f9f29a60000)]

Stack: [0x00007f9f29960000,0x00007f9f29a60000],  sp=0x00007f9f29a5e330,  free space=1016k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V  [libjvm.so+0xa2f59a]  VMError::report_and_die()+0x2ca
V  [libjvm.so+0x4b2e4b]  report_vm_out_of_memory(char const*, int, unsigned long, VMErrorType, char const*)+0x8b
V  [libjvm.so+0x89e3b3]  os::Linux::commit_memory_impl(char*, unsigned long, bool)+0x103
V  [libjvm.so+0x89e909]  os::pd_commit_memory(char*, unsigned long, unsigned long, bool)+0x29
V  [libjvm.so+0x8985ba]  os::commit_memory(char*, unsigned long, unsigned long, bool)+0x2a
V  [libjvm.so+0x9091c3]  PSVirtualSpace::expand_by(unsigned long)+0x53
V  [libjvm.so+0x8b683e]  ParMarkBitMap::initialize(MemRegion)+0x13e
V  [libjvm.so+0x8ff1c9]  PSParallelCompact::initialize()+0x149
V  [libjvm.so+0x8bf6fd]  ParallelScavengeHeap::initialize()+0x35d
V  [libjvm.so+0x9fd733]  Universe::initialize_heap()+0xe3
V  [libjvm.so+0x9fdb74]  universe_init()+0x64
V  [libjvm.so+0x5d46d5]  init_globals()+0x65
V  [libjvm.so+0x9e445d]  Threads::create_vm(JavaVMInitArgs*, bool*)+0x24d
V  [libjvm.so+0x665b04]  JNI_CreateJavaVM+0x74
C  [libjli.so+0x703e]  JavaMain+0x9e

1.以上表示导致出错的线程是0x00007f9f20009000（指针），线程类型是JavaThread，JavaThread表示执行的是java线程，关于该线程其它类型还可能是：

VMThread：jvm的内部线程
CompilerThread：用来调用JITing，实时编译装卸class 。通常，jvm会启动多个线程来处理这部分工作，线程名称后面的数字也会累加，例如：CompilerThread1
GCTaskThread：执行gc的线程
WatcherThread：jvm周期性任务调度的线程，是一个单例对象。该线程在JVM内使用得比较频繁，比如：定期的内存监控、JVM运行状况监控，还有我们经常需要去执行一些jstat 这类命令查看gc的情况
ConcurrentMarkSweepThread：jvm在进行CMS GC的时候，会创建一个该线程去进行GC，该线程被创建的同时会创建一个SurrogateLockerThread（简称SLT）线程并且启动它，SLT启动之后，处于等待阶段。CMST开始GC时，会发一个消息给SLT让它去获取Java层Reference对象的全局锁：Lock

2.后面的”Unknown thread”位置显示线程名，如果后面有“daemon”表示该线程为守护线程，再后面的“[_thread_in_vm”表示线程正在执行虚拟机代码，关于该描述其它类型还可能是：

_thread_in_native：线程当前状态
thread_uninitialized：线程还没有创建，它只在内存原因崩溃的时候才出现
_thread_new：线程已经被创建，但是还没有启动
thread_in_native：线程正在执行本地代码，一般这种情况很可能是本地代码有问题
_ thread_in_vm：线程正在执行虚拟机代码
_ thread_in_Java：线程正在执行解释或者编译后的Java代码
thread_blocked：线程处于阻塞状态
…_trans：以_trans结尾，线程正处于要切换到其它状态的中间状态

最后的“id=77666”表线程ID，stack(0x00007f9f29960000,0x00007f9f29a60000)表示栈区间。
详细信息显示commit_memory错误，即无法申请内存。一般是因为 Xmx 设置过大，超过系统可用内存，JVM 申请内存失败。

进程信息

---------------  P R O C E S S  ---------------

Java Threads: ( => current thread )
#所有线程信息
Other Threads:

=>0x00007f9f20009000 (exited) JavaThread "Unknown thread" [_thread_in_vm, id=77666, stack(0x00007f9f29960000,0x00007f9f29a60000)]
#安全点和锁信息
VM state:not at safepoint (not fully initialized)
VM Mutex/Monitor currently owned by a thread: None

GC Heap History (0 events):
No events

Deoptimization events (0 events):
No events

Internal exceptions (0 events):
No events

Events (0 events):
No events

安全点和锁信息

安全线信息为正常运行，其它可能得描述还有：

not at a safepoint：正常运行状态
at safepoint：所有线程都因为虚拟机等待状态而阻塞，等待一个虚拟机操作完成
synchronizing：一个特殊的虚拟机操作，要求虚拟机内的其它线程保持等待状态

锁信息为未被线程持有，Mutex是虚拟机内部的锁，而Monitor则是synchronized锁或者其它关联到的Java对象。

jvm内存映射

Dynamic libraries:
00400000-00401000 r-xp 00000000 fd:00 1209105                            /usr/local/java/jdk1.8.0_11/bin/jstack
00600000-00601000 rw-p 00000000 fd:00 1209105                            /usr/local/java/jdk1.8.0_11/bin/jstack
00962000-00983000 rw-p 00000000 00:00 0                                  [heap]
4c8000000-4c8680000 rw-p 00000000 00:00 0 
4c8680000-6c2b00000 ---p 00000000 00:00 0 
6c2b00000-6c2c80000 rw-p 00000000 00:00 0 
6c2c80000-7c0000000 ---p 00000000 00:00 0 
......

这些信息是虚拟机崩溃时的虚拟内存列表区域。它可以告诉你崩溃原因时哪些类库正在被使用，位置在哪里，还有堆栈和守护页信息。以列表中第一条为例介绍下：

00400000-00401000：内存区域
r-xp：权限，r/w/x/p/s分别表示读/写/执行/私有/共享
00000000：文件内的偏移量
fd:00：文件位置的majorID和minorID
1209105：索引节点号
/usr/local/java/jdk1.8.0_11/bin/jstack：文件位置

服务器信息

上面是内存信息，主要关注下swap信息，看看有没有使用虚拟内存；下面是cpu信息

OS:CentOS Linux release 7.6.1810 (Core) 
uname:Linux 3.10.0-957.el7.x86_64 #1 SMP Thu Nov 8 23:39:32 UTC 2018 x86_64
libc:glibc 2.17 NPTL 2.17 
rlimit: STACK 8192k, CORE 0k, NPROC 63373, NOFILE 4096, AS infinity
load average:1.80 1.52 1.08

/proc/meminfo:
MemTotal:       49802248 kB
MemFree:          238684 kB
MemAvailable:     159440 kB
Buffers:               0 kB
Cached:           101520 kB
SwapCached:        43900 kB
Active:         45037612 kB
Inactive:        3103068 kB
......

CPU:total 16 (1 cores per cpu, 1 threads per core) family 6 model 85 stepping 7, cmov, cx8, fxsr, mmx, sse, sse2, sse3, ssse3, sse4.1, sse4.2, popcnt, avx, avx2, aes, clmul, erms, tsc, tscinvbit

/proc/cpuinfo:
processor	: 0
vendor_id	: GenuineIntel
cpu family	: 6
model		: 85
model name	: Intel(R) Xeon(R) Gold 5220 CPU @ 2.20GHz
stepping	: 7
microcode	: 0x5002f01
cpu MHz		: 2200.000
cache size	: 25344 KB
......

# 随笔