hs_err_pid.log - 详解

发表于 | 分类于 
# There is insufficient memory for the Java Runtime Environment to continue.
# Native memory allocation (mmap) failed to map 12288 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:2673), pid=13016, tid=140682742126336
#
# JRE version: Java(TM) SE Runtime Environment (8.0_40-b25) (build 1.8.0_40-b25)
# Java VM: Java HotSpot(TM) 64-Bit Server VM (25.40-b25 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

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

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

Stack: [0x00007ff340ced000,0x00007ff340dee000],  sp=0x00007ff340dec9a0,  free space=1022k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V  [libjvm.so+0xaaca9a]  VMError::report_and_die()+0x2ba
V  [libjvm.so+0x4f333b]  report_vm_out_of_memory(char const*, int, unsigned long, VMErrorType, char const*)+0x8b
V  [libjvm.so+0x90e8c3]  os::Linux::commit_memory_impl(char*, unsigned long, bool)+0x103
V  [libjvm.so+0x90e98c]  os::pd_commit_memory(char*, unsigned long, bool)+0xc
V  [libjvm.so+0x90772a]  os::commit_memory(char*, unsigned long, bool)+0x2a
V  [libjvm.so+0x90c97f]  os::pd_create_stack_guard_pages(char*, unsigned long)+0x7f
V  [libjvm.so+0xa52b4e]  JavaThread::create_stack_guard_pages()+0x5e
V  [libjvm.so+0xa5c9b4]  JavaThread::run()+0x34
V  [libjvm.so+0x910ee8]  java_start(Thread*)+0x108
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中比较重要的一个部分。

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

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

这一部分是crash时Java代码中所有线程的状况。分析类似上一部分。
VM state:not at safepoint (normal execution)
VM Mutex/Monitor currently owned by a thread: None

VM状态：

状态 描述
not at a safepoint 正常执行
at safepoint 所有VM内的线程被block住，在等待某一个VM操作完成
synchronizing 一个特殊VM操作需要执行，VM在等待所有线程block 
Heap:
 PSYoungGen  total 39424K, used 31166K [0x0000000771a00000, 0x0000000774780000, 0x00000007c0000000)
  eden space 38912K, 79% used [0x0000000771a00000,0x000000077384faf0,0x0000000774000000)
  from space 512K, 25% used [0x0000000774680000,0x00000007746a0000,0x0000000774700000)
  to   space 512K, 0% used [0x0000000774700000,0x0000000774700000,0x0000000774780000)
 ParOldGen   total 124928K, used 67043K [0x00000006d4e00000, 0x00000006dc800000, 0x0000000771a00000)
  object space 124928K, 53% used [0x00000006d4e00000,0x00000006d8f78d18,0x00000006dc800000)
 Metaspace   used 54122K, capacity 54748K, committed 54912K, reserved 1097728K
  class spaceused 6562K, capacity 6716K, committed 6784K, reserved 1048576K

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

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

Polling page: 0x00007ff369d84000

CodeCache: size=245760Kb used=17958Kb max_used=18385Kb free=227801Kb
 bounds [0x00007ff34aad9000, 0x00007ff34bd29000, 0x00007ff359ad9000]
 total_blobs=6019 nmethods=5425 adapters=516
 compilation: enabled
  • Card Table是jvm维护的一种数据结构，用于记录更改对象时的引用，方便GC。
  • CodeCache是用来保存本地代码的，不属于PermGen。
Compilation events (10 events):
GC Heap History (10 events):
Deoptimization events (10 events):
Internal exceptions (10 events):
Events (10 events):
Dynamic libraries:

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

Events (10 events):
Event: 2603309.010 Thread 0x00007ff2c800c000 DEOPT UNPACKING pc=0x00007ff34aaddf69 sp=0x00007ff3409e88a8 mode 2
Event: 2603310.108 Thread 0x00007ff362229000 DEOPT PACKING pc=0x00007ff34b25ce6c sp=0x00007ff340ceb660
Event: 2603310.122 Thread 0x00007ff2c8009800 Uncommon trap: trap_request=0xffffff65 fr.pc=0x00007ff34b890e40
Event: 2603310.124 Thread 0x00007ff2c8009800 DEOPT PACKING pc=0x00007ff34b890e40 sp=0x00007ff3408e7790
Event: 2603310.124 Thread 0x00007ff2c8009800 DEOPT UNPACKING pc=0x00007ff34aaddf69 sp=0x00007ff3408e7680 mode 2
Event: 2603310.125 Thread 0x00007ff2c8009800 Uncommon trap: trap_request=0xffffff65 fr.pc=0x00007ff34b850fe4
Event: 2603310.125 Thread 0x00007ff2c8009800 DEOPT PACKING pc=0x00007ff34b850fe4 sp=0x00007ff3408e7560
Event: 2603310.125 Thread 0x00007ff2c8009800 DEOPT UNPACKING pc=0x00007ff34aaddf69 sp=0x00007ff3408e72d8 mode 2
Event: 2603310.126 Thread 0x00007ff362229000 DEOPT UNPACKING pc=0x00007ff34aaddf69 sp=0x00007ff340ceb628 mode 2
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）。

---------------  S Y S T E M  ---------------

OS:Amazon Linux AMI release 2016.03

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

/proc/meminfo:
MemTotal:   15403948 kB
MemFree: 2637700 kB
MemAvailable:2571132 kB
Buffers: 304 kB
Cached:13784 kB
SwapCached:0 kB
Active: 12625320 kB
Inactive:   7684 kB
Active(anon):   12619252 kB
Inactive(anon):  336 kB
Active(file):   6068 kB
Inactive(file): 7348 kB
Unevictable:   0 kB
Mlocked:   0 kB
SwapTotal: 0 kB
SwapFree:  0 kB
Dirty:16 kB
Writeback:56 kB
AnonPages:  12606968 kB
Mapped:10896 kB
Shmem:   356 kB
Slab:  46004 kB
SReclaimable:  22384 kB
SUnreclaim:23620 kB
KernelStack:9856 kB
PageTables:38084 kB
NFS_Unstable:  0 kB
Bounce:0 kB
WritebackTmp:  0 kB
CommitLimit: 7701972 kB
Committed_AS:   18337652 kB
VmallocTotal:   34359738367 kB
VmallocUsed:   0 kB
VmallocChunk:  0 kB
AnonHugePages: 0 kB
HugePages_Total:   0
HugePages_Free:0
HugePages_Rsvd:0
HugePages_Surp:0
Hugepagesize:   2048 kB
DirectMap4k:   12288 kB
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 ..