hs_err_pid.log - 详解

2018/04/11

JVM 错误日志 hs_err_pid.log 详解，包括内存不足、Native memory allocation 失败等问题的原因和解决方案。

1
# There is insufficient memory for the Java Runtime Environment to continue.
2
# Native memory allocation (mmap) failed to map 12288 bytes for committing reserved memory.
3
# Possible reasons:
4
#   The system is out of physical RAM or swap space
5
#   In 32 bit mode, the process size limit was hit
6
# Possible solutions:
7
#   Reduce memory load on the system
8
#   Increase physical memory or swap space
9
#   Check if swap backing store is full
10
#   Use 64 bit Java on a 64 bit OS
11
#   Decrease Java heap size (-Xmx/-Xms)
12
#   Decrease number of Java threads
13
#   Decrease Java thread stack sizes (-Xss)
14
#   Set larger code cache with -XX:ReservedCodeCacheSize=
15
# This output file may be truncated or incomplete.
16
#
17
#  Out of Memory Error (os_linux.cpp:2673), pid=13016, tid=140682742126336
18
#
19
# JRE version: Java(TM) SE Runtime Environment (8.0_40-b25) (build 1.8.0_40-b25)
20
# Java VM: Java HotSpot(TM) 64-Bit Server VM (25.40-b25 mixed mode linux-amd64 compressed oops)
21
# Failed to write core dump. Core dumps have been disabled. To enable core dumping, try "ulimit -c unlimited" before starting Java again

第一部分主要是程序crash的原因以及相关的solution。

1
Current thread (0x00007ff2d8001000):  JavaThread "flink-akka.remote.default-remote-dispatcher-15" daemon [_thread_new, id=31925, stack(0x00007ff340ced000,0x00007ff340dee000)]
2

3
Stack: [0x00007ff340ced000,0x00007ff340dee000],  sp=0x00007ff340dec9a0,  free space=1022k
4
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
5
V  [libjvm.so+0xaaca9a]  VMError::report_and_die()+0x2ba
6
V  [libjvm.so+0x4f333b]  report_vm_out_of_memory(char const*, int, unsigned long, VMErrorType, char const*)+0x8b
7
V  [libjvm.so+0x90e8c3]  os::Linux::commit_memory_impl(char*, unsigned long, bool)+0x103
8
V  [libjvm.so+0x90e98c]  os::pd_commit_memory(char*, unsigned long, bool)+0xc
9
V  [libjvm.so+0x90772a]  os::commit_memory(char*, unsigned long, bool)+0x2a
10
V  [libjvm.so+0x90c97f]  os::pd_create_stack_guard_pages(char*, unsigned long)+0x7f
11
V  [libjvm.so+0xa52b4e]  JavaThread::create_stack_guard_pages()+0x5e
12
V  [libjvm.so+0xa5c9b4]  JavaThread::run()+0x34
13
V  [libjvm.so+0x910ee8]  java_start(Thread*)+0x108
14
C  [libpthread.so.0+0x7dc5]  start_thread+0xc5

Current Thread表示crash时程序所处的线程。 线程类别: JavaThread，共有以下几种

JavaThread
VMThread（负责VM内的一些操作，包括GC）
CompilerThread
GCTaskThread
WatcherThread
ConcurrentMarkSweepThread

线程状态：_thread_new

线程状态 | 描述

| - _thread_uninitialized | 线程未被创建 _thread_new | 线程创建但并未执行 _thread_in_native | 线程正在运行native code _thread_in_vm | 执行VM的code _thread_in_java | 执行java的code _thread_blocked | 被block住的线程

原生堆栈信息（Native frames）: 主要是一些jvm动态库的对战信息，是分析crash中比较重要的一个部分。

1
Java Threads: ( => current thread )
2
=>0x00007ff2d8001000 JavaThread "flink-akka.remote.default-remote-dispatcher-15" daemon [_thread_new, id=31925, stack(0x00007ff340ced000,0x00007ff340dee000)]
3
  0x00007ff2ec053800 JavaThread "Hashed wheel timer #1" daemon [_thread_blocked, id=14219, stack(0x00007ff33bdfe000,0x00007ff33beff000)]
4
  0x00007ff2dc130800 JavaThread "New I/O server boss #6" daemon [_thread_in_native, id=14218, stack(0x00007ff33beff000,0x00007ff33c000000)]
5
  0x00007ff2dc119800 JavaThread "New I/O worker #5" daemon [_thread_in_native, id=14217, stack(0x00007ff3400e3000,0x00007ff3401e4000)]
6
  0x00007ff2dc0b6000 JavaThread "New I/O worker #4" daemon [_thread_in_native, id=14216, stack(0x00007ff3401e4000,0x00007ff3402e5000)]
7
  0x00007ff2dc0bb800 JavaThread "New I/O boss #3" daemon [_thread_in_native, id=14215, stack(0x00007ff3402e5000,0x00007ff3403e6000)]
8
  0x00007ff2dc05c000 JavaThread "New I/O worker #2" daemon [_thread_in_native, id=14214, stack(0x00007ff3403e6000,0x00007ff3404e7000)]
9
  0x00007ff2dc052000 JavaThread "New I/O worker #1" daemon [_thread_in_native, id=14213, stack(0x00007ff3404e7000,0x00007ff3405e8000)]
10
  0x00007ff2c8009800 JavaThread "flink-akka.remote.default-remote-dispatcher-7" daemon [_thread_in_vm, id=14206, stack(0x00007ff3407e8000,0x00007ff3408e9000)]
11
  0x00007ff2c800c000 JavaThread "flink-akka.remote.default-remote-dispatcher-6" daemon [_thread_in_native, id=14202, stack(0x00007ff3408e9000,0x00007ff3409ea000)]
12
  0x00007ff2cc020000 JavaThread "flink-akka.actor.default-dispatcher-5" daemon [_thread_blocked, id=14147, stack(0x00007ff3409ea000,0x00007ff340aeb000)]
13
  0x00007ff36222a800 JavaThread "flink-akka.actor.default-dispatcher-4" daemon [_thread_blocked, id=14136, stack(0x00007ff340aeb000,0x00007ff340bec000)]
14
  0x00007ff362229000 JavaThread "flink-akka.actor.default-dispatcher-3" daemon [_thread_blocked, id=14135, stack(0x00007ff340bec000,0x00007ff340ced000)]
15
  0x00007ff362183000 JavaThread "flink-scheduler-1" daemon [_thread_blocked, id=14044, stack(0x00007ff340fee000,0x00007ff3410ef000)]
16
  0x00007ff3614b4000 JavaThread "Timer for 'phoenix' metrics system" daemon [_thread_blocked, id=14032, stack(0x00007ff342dfa000,0x00007ff342efb000)]
17
  0x00007ff360fc1000 JavaThread "main-EventThread" daemon [_thread_blocked, id=14031, stack(0x00007ff3431fc000,0x00007ff3432fd000)]
18
  0x00007ff360faf000 JavaThread "main-SendThread(cnzk2:2181)" daemon [_thread_in_native, id=14030, stack(0x00007ff3432fd000,0x00007ff3433fe000)]
19
  0x00007ff360471000 JavaThread "Thread-80" daemon [_thread_blocked, id=14029, stack(0x00007ff3430fb000,0x00007ff3431fc000)]
20
  0x00007ff3608a7000 JavaThread "IPC Parameter Sending Thread #0" daemon [_thread_blocked, id=13178, stack(0x00007ff3437fe000,0x00007ff3438ff000)]
21
  0x00007ff3608a4000 JavaThread "IPC Client (1508059488) connection to cnhm0/10.0.1.222:8032 from apps" daemon [_thread_blocked, id=13177, stack(0x00007ff348923000,0x00007ff348a24000)]
22
  0x00007ff3600df800 JavaThread "Service Thread" daemon [_thread_blocked, id=13172, stack(0x00007ff3498c5000,0x00007ff3499c6000)]
23
  0x00007ff3600d2000 JavaThread "C1 CompilerThread2" daemon [_thread_in_native, id=13171, stack(0x00007ff3499c6000,0x00007ff349ac7000)]
24
  0x00007ff3600d0000 JavaThread "C2 CompilerThread1" daemon [_thread_blocked, id=13170, stack(0x00007ff349ac7000,0x00007ff349bc8000)]
25
  0x00007ff3600cd000 JavaThread "C2 CompilerThread0" daemon [_thread_blocked, id=13169, stack(0x00007ff349bc8000,0x00007ff349cc9000)]
26
  0x00007ff3600cb000 JavaThread "JDWP Event Helper Thread" daemon [_thread_blocked, id=13168, stack(0x00007ff349cc9000,0x00007ff349dca000)]
27
  0x00007ff3600c7000 JavaThread "JDWP Transport Listener: dt_socket" daemon [_thread_in_native, id=13167, stack(0x00007ff349dca000,0x00007ff349ecb000)]
28
  0x00007ff3600b8000 JavaThread "Signal Dispatcher" daemon [_thread_blocked, id=13166, stack(0x00007ff34a0cf000,0x00007ff34a1d0000)]
29
  0x00007ff36008c000 JavaThread "Finalizer" daemon [_thread_blocked, id=13165, stack(0x00007ff34a1d0000,0x00007ff34a2d1000)]
30
  0x00007ff36008a000 JavaThread "Reference Handler" daemon [_thread_blocked, id=13164, stack(0x00007ff34a2d1000,0x00007ff34a3d2000)]
31
  0x00007ff360017000 JavaThread "main" [_thread_blocked, id=13158, stack(0x00007ff369c7a000,0x00007ff369d7b000)]
32

33
Other Threads:
34
  0x00007ff360085000 VMThread [stack: 0x00007ff34a3d2000,0x00007ff34a4d3000] [id=13163]
35
  0x00007ff3600e2000 WatcherThread [stack: 0x00007ff3497c4000,0x00007ff3498c5000] [id=13173]

这一部分是crash时Java代码中所有线程的状况。分析类似上一部分。

1
VM state:not at safepoint (normal execution)
2
VM Mutex/Monitor currently owned by a thread: None

VM状态：

状态 | 描述

| :-: | not at a safepoint | 正常执行 at safepoint | 所有VM内的线程被block住，在等待某一个VM操作完成 synchronizing | 一个特殊VM操作需要执行，VM在等待所有线程block

1
Heap:
2
 PSYoungGen  total 39424K, used 31166K [0x0000000771a00000, 0x0000000774780000, 0x00000007c0000000)
3
  eden space 38912K, 79% used [0x0000000771a00000,0x000000077384faf0,0x0000000774000000)
4
  from space 512K, 25% used [0x0000000774680000,0x00000007746a0000,0x0000000774700000)
5
  to   space 512K, 0% used [0x0000000774700000,0x0000000774700000,0x0000000774780000)
6
 ParOldGen   total 124928K, used 67043K [0x00000006d4e00000, 0x00000006dc800000, 0x0000000771a00000)
7
  object space 124928K, 53% used [0x00000006d4e00000,0x00000006d8f78d18,0x00000006dc800000)
8
 Metaspace   used 54122K, capacity 54748K, committed 54912K, reserved 1097728K
9
  class spaceused 6562K, capacity 6716K, committed 6784K, reserved 1048576K
10

11
Card table byte_map: [0x00007ff3664db000,0x00007ff366c35000] byte_map_base: 0x00007ff362e34000
12

13
Marking Bits: (ParMarkBitMap*) 0x00007ff3691426c0
14
 Begin Bits: [0x00007ff324a70000, 0x00007ff328538000)
15
 End Bits:   [0x00007ff328538000, 0x00007ff32c000000)
16

17
Polling page: 0x00007ff369d84000
18

19
CodeCache: size=245760Kb used=17958Kb max_used=18385Kb free=227801Kb
20
 bounds [0x00007ff34aad9000, 0x00007ff34bd29000, 0x00007ff359ad9000]
21
 total_blobs=6019 nmethods=5425 adapters=516
22
 compilation: enabled

Card Table是jvm维护的一种数据结构，用于记录更改对象时的引用，方便GC。
CodeCache是用来保存本地代码的，不属于PermGen。

1
Compilation events (10 events):
2
GC Heap History (10 events):
3
Deoptimization events (10 events):
4
Internal exceptions (10 events):
5
Events (10 events):
6
Dynamic libraries:

这些都是表示crash时jvm最近的一些操作。举个例子说明：

1
Events (10 events):
2
Event: 2603309.010 Thread 0x00007ff2c800c000 DEOPT UNPACKING pc=0x00007ff34aaddf69 sp=0x00007ff3409e88a8 mode 2
3
Event: 2603310.108 Thread 0x00007ff362229000 DEOPT PACKING pc=0x00007ff34b25ce6c sp=0x00007ff340ceb660
4
Event: 2603310.122 Thread 0x00007ff2c8009800 Uncommon trap: trap_request=0xffffff65 fr.pc=0x00007ff34b890e40
5
Event: 2603310.124 Thread 0x00007ff2c8009800 DEOPT PACKING pc=0x00007ff34b890e40 sp=0x00007ff3408e7790
6
Event: 2603310.124 Thread 0x00007ff2c8009800 DEOPT UNPACKING pc=0x00007ff34aaddf69 sp=0x00007ff3408e7680 mode 2
7
Event: 2603310.125 Thread 0x00007ff2c8009800 Uncommon trap: trap_request=0xffffff65 fr.pc=0x00007ff34b850fe4
8
Event: 2603310.125 Thread 0x00007ff2c8009800 DEOPT PACKING pc=0x00007ff34b850fe4 sp=0x00007ff3408e7560
9
Event: 2603310.125 Thread 0x00007ff2c8009800 DEOPT UNPACKING pc=0x00007ff34aaddf69 sp=0x00007ff3408e72d8 mode 2
10
Event: 2603310.126 Thread 0x00007ff362229000 DEOPT UNPACKING pc=0x00007ff34aaddf69 sp=0x00007ff340ceb628 mode 2
11
Event: 2603310.935 Thread 0x00007ff2d8001000 Thread added: 0x00007ff2d8001000

上述是最近10个runtime VM的事件，拿第一条举例，2603309.010是从VM启动后的时长，单位是秒，pc是program counter，sp是stack pointer。关于 DEOPT、Uncommon trap等的解释可以看这个issue，大概就是编译的时候，编译器做了一些优化，但是在runtime时发现这个优化没有用，所以叫去优化（deoptimization）。

1
---------------  S Y S T E M  ---------------
2

3
OS:Amazon Linux AMI release 2016.03
4

5
uname:Linux 4.4.11-23.53.amzn1.x86_64 #1 SMP Wed Jun 1 22:22:50 UTC 2016 x86_64
6
libc:glibc 2.17 NPTL 2.17
7
rlimit: STACK 8192k, CORE 0k, NPROC 65536, NOFILE 65536, AS infinity
8
load average:10.84 2.76 1.17
9

10
/proc/meminfo:
11
MemTotal:   15403948 kB
12
MemFree: 2637700 kB
13
MemAvailable:2571132 kB
14
Buffers: 304 kB
15
Cached:13784 kB
16
SwapCached:0 kB
17
Active: 12625320 kB
18
Inactive:   7684 kB
19
Active(anon):   12619252 kB
20
Inactive(anon):  336 kB
21
Active(file):   6068 kB
22
Inactive(file): 7348 kB
23
Unevictable:   0 kB
24
Mlocked:   0 kB
25
SwapTotal: 0 kB
26
SwapFree:  0 kB
27
Dirty:16 kB
28
Writeback:56 kB
29
AnonPages:  12606968 kB
30
Mapped:10896 kB
31
Shmem:   356 kB
32
Slab:  46004 kB
33
SReclaimable:  22384 kB
34
SUnreclaim:23620 kB
35
KernelStack:9856 kB
36
PageTables:38084 kB
37
NFS_Unstable:  0 kB
38
Bounce:0 kB
39
WritebackTmp:  0 kB
40
CommitLimit: 7701972 kB
41
Committed_AS:   18337652 kB
42
VmallocTotal:   34359738367 kB
43
VmallocUsed:   0 kB
44
VmallocChunk:  0 kB
45
AnonHugePages: 0 kB
46
HugePages_Total:   0
47
HugePages_Free:0
48
HugePages_Rsvd:0
49
HugePages_Surp:0
50
Hugepagesize:   2048 kB
51
DirectMap4k:   12288 kB
52
DirectMap2M:15716352 kB

系统内存情况：

名词 | 描述 | 名词 | 描述 | 名词 | 描述

| :-: | :-: | :-: | :-: | :- MemToal | 总内存 | MemFree | 未使用内存 | MemAvailable | 可用内存 Buffers | 文件读写Buffer | Cached | 缓存 | SwapCached | 缓存的交换空间 Active | 最近被申请过的空间 | Inactive | 最近未被申请过的空间 | Active(anon) | .. Inactive(anon) | .. | Active(file) | .. | Inactive(file) | .. Unevictable | .. | Unevictable | .. | Mlocked | .. SwapTotal | 可用交换空间 | SwapFree | 可用交换空间 | Dirty | 等待写入磁盘的空间 Writeback | 正在被写入磁盘的空间 | AnonPages | .. | Mapped | .. Shmem | .. | Slab | kernel使用 | Sreclaimable | .. SUnreclaim | .. | KernelStack | .. | PageTables | 内存页映射表空间 NFS_Unstable | .. | Bounce | .. | WritebackTmp | .. CommitLimit | .. | Committed_AS | 完成workload最坏情况的内存使用情况 | VmallocTotal | .. VmallocUsed | 虚拟空间可映射的大小 | VmallocUsed | 已使用的虚拟空间映射大小 | VmallocChunk | 虚拟空间最大的虚拟空间块 AnonHugePages | .. | HugePages_Total | .. | HugePages_Free | .. HugePages_Rsvd | .. | HugePages_Surp | .. | Hugepagesize | .. DirectMap4k | .. | DirectMap2M | ..