JVM fatal error log (hs_err_pid.log) analysis
CrashAnalysis
Function introduction
This is a jvm crash analysis tool, which mainly analyzes the causes of jvm crash and common solutions.
Mode of use
java -jar CrashAnalysis-1.0-SNAPSHOT.jar ${hs_err_pid.log}
${hs_err_pid.log} is the log generated after the jvm crash.
effect
After the analysis, the diagnostic information will be displayed, and other information is used to verify the diagnostic information.
In the last two days, a service in the test environment always hangs (once every two to three days), and the JVM virtual machine always crashes. Therefore, it is necessary to understand the cause of JVM crash.
When the JVM crashes due to a fatal error, an HS is generated_ err_ pid_ xxx. Log, which contains important information that causes JVM crash. By analyzing this file, we can locate the cause of JVM crash, so as to repair and ensure system stability.
By default, the file is generated in the working directory. Of course, you can also specify the generation path through JVM parameters:
-XX:ErrorFile=/var/log/hs_err_pid<pid>.log1
This document mainly includes the following contents:
- Log header file
- Thread information causing crash
- All thread information
- Safety point and lock information
- Heap information
- Local code cache
- Compile event
- gc related records
- jvm memory mapping
- jvm startup parameters
- server information
Next, it will be parsed step by step according to the contents of this file.
Log header file
The contents are as follows
# # A fatal error has been detected by the Java Runtime Environment: # # SIGSEGV (0xb) at pc=0x0000003797807a91, pid=29071, tid=139901421901568 # # JRE version: Java(TM) SE Runtime Environment (8.0_45-b14) (build 1.8.0_45-b14) # Java VM: Java HotSpot(TM) 64-Bit Server VM (25.45-b02 mixed mode linux-amd64 compressed oops) # Problematic frame: # C [libresolv.so.2+0x7a91] __libc_res_nquery+0x1c1 # # Failed to write core dump. Core dumps have been disabled. To enable core dumping, try "ulimit -c unlimited" before starting Java again # # If you would like to submit a bug report, please visit: # http://bugreport.java.com/bugreport/crash.jsp # The crash happened outside the Java Virtual Machine in native code. # See problematic frame for where to report the bug. #1234567891011121314151617
This paragraph mainly describes the causes of JVM Crash. Common causes include JVM bug s, application errors, JVM parameters, insufficient server resources, JNI call errors, etc. Of course, there are some version and configuration information,
SIGSEGV (0xb) at pc=0x0000003797807a91, pid=29071, tid=1399014219015681
Unexpected error detected by JRE, where
- SIGSEGV: semaphore
- 0xb: signal code
- pc=0x0000003797807a91: value of program counter
- pid=29071: process number
- tid=139901421901568: thread number
SIGSEGV(0xb) indicates that the JNI code is being executed when the JVM crashes. The common description also includes EXCEPTION_ACCESS_VIOLATION: this description indicates that the JVM is executing its own code when it crashes, which is often caused by the Bug of the JVM; Another common description is EXCEPTION_STACK_OVERFLOW, this description indicates that this is an error caused by stack overflow, which is often caused by deep recursion in the application.
# JRE version: Java(TM) SE Runtime Environment (8.0_45-b14) (build 1.8.0_45-b14) # Java VM: Java HotSpot(TM) 64-Bit Server VM (25.45-b02 mixed mode linux-amd64 compressed oops)12
Version information of JRE and JVM
# Problematic frame: # C [libresolv.so.2+0x7a91] __libc_res_nquery+0x1c112
This information is important. The problem frame information is:
C indicates that the frame type is local frame, and there are other types:
- j: Interpreted Java frames
- V: virtual machine frame
- v: Stub stack frame generated by virtual machine
- J: Other frame types, including compiled Java frames
[libresolv.so.2+0x7a91] __libc_res_nquery+0x1c1 has the same meaning as the program counter (pc), but it uses the way of local so library + offset.
Thread information causing crash
The contents are as follows:
--------------- T H R E A D --------------- Current thread (0x0000000001e94800): JavaThread "pool-1-thread-2" [_thread_in_native, id=30111, stack(0x00007f3d567e5000,0x00007f3d568e6000)] siginfo: si_signo: 11 (SIGSEGV), si_code: 1 (SEGV_MAPERR), si_addr: 0x0000000000000003 Registers: RAX=0x0000000000000000, RBX=0x0000000000000000, RCX=0x0000000000000000, RDX=0x0000000000000050 RSP=0x00007f3d568e2280, RBP=0x00007f3d568e2570, RSI=0x0000000000000000, RDI=0x00000000ffffffff R8 =0x0000000000000000, R9 =0x0000000000000000, R10=0x000000000007a337, R11=0x0000000000000213 R12=0x00007f3d568e2ef0, R13=0x00007f3d568e22b0, R14=0x0000000000000000, R15=0x00007f3d568e5db8 RIP=0x0000003797807a91, EFLAGS=0x0000000000010246, CSGSFS=0x0000000000000033, ERR=0x0000000000000004 TRAPNO=0x000000000000000e Top of Stack: (sp=0x00007f3d568e2280) 0x00007f3d568e2280: b8e4bfb900000800 00007f3d568e3760 0x00007f3d568e2290: 00007f3d568e3758 00007f3d568e377c 0x00007f3d568e22a0: 00007f3d568e3778 6f6e6b6e56a88a58 0x00007f3d568e22b0: 00000100000149a0 7a68710800000000 0x00007f3d568e22c0: 6970067363642d78 6d6f63036e61676e ....ellipsis Instructions: (pc=0x0000003797807a91) 0x0000003797807a71: 48 89 45 b8 48 8b 4d b8 0f b6 51 03 89 d3 83 e3 0x0000003797807a81: 0f 75 0d 0f b7 49 06 66 c1 c9 08 66 85 c9 75 4f 0x0000003797807a91: 0f b6 48 03 bf 0f 00 00 00 40 20 cf 75 0d 0f b7 0x0000003797807aa1: 70 06 66 c1 ce 08 66 85 f6 75 34 83 e1 0f 83 e2 Register to memory mapping: RAX=0x0000000000000000 is an unknown value RBX=0x0000000000000000 is an unknown value RCX=0x0000000000000000 is an unknown value RDX=0x0000000000000050 is an unknown value RSP=0x00007f3d568e2280 is pointing into the stack for thread: 0x0000000001e94800 RBP=0x00007f3d568e2570 is pointing into the stack for thread: 0x0000000001e94800 ... ellipsis Stack: [0x00007f3d567e5000,0x00007f3d568e6000], sp=0x00007f3d568e2280, free space=1012k Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code) C [libresolv.so.2+0x7a91] __libc_res_nquery+0x1c1 C [libresolv.so.2+0x7fd1] Java frames: (J=compiled Java code, j=interpreted, Vv=VM code) J 15056 java.net.Inet6AddressImpl.lookupAllHostAddr(Ljava/lang/String;)[Ljava/net/InetAddress; (0 bytes) @ 0x00007f3d7492af8c [0x00007f3d7492af40+0x4c] J 14966 C1 java.net.InetAddress.getAddressesFromNameService(Ljava/lang/String;Ljava/net/InetAddress;)[Ljava/net/InetAddress; (245 bytes) @ 0x00007f3d75466754 [0x00007f3d754662c0+0x494] J 14291 C2 java.net.InetAddress.getAllByName(Ljava/lang/String;Ljava/net/InetAddress;)[Ljava/net/InetAddress; (387 bytes) @ 0x00007f3d7534b718 [0x00007f3d7534ae20+0x8f8] J 14178 C1 java.net.InetSocketAddress.<init>(Ljava/lang/String;I)V (47 bytes) @ 0x00007f3d752ce0f4 [0x00007f3d752cdec0+0x234] j sun.security.ssl.SSLSocketImpl.<init>(Lsun/security/ssl/SSLContextImpl;Ljava/lang/String;ILjava/net/InetAddress;I)V+144 j sun.security.ssl.SSLSocketFactoryImpl.createSocket(Ljava/lang/String;ILjava/net/InetAddress;I)Ljava/net/Socket;+13 j com.ufclub.daq.qhzx.utils.SSLProtocolSocketFactory.createSocket(Ljava/lang/String;ILjava/net/InetAddress;I)Ljava/net/Socket;+15 .... Omit code 123456789101121314151617181920212223242526272829303313233435363738394041424344454647484950515253
This section contains the thread details and thread stack of the starting JVM fatal error.
Thread information
Current thread (0x0000000001e94800): JavaThread "pool-1-thread-2" [_thread_in_native, id=30111, stack(0x00007f3d567e5000,0x00007f3d568e6000)]1
- 0x000000000 1e94800: thread pointer in error
- JavaThread: thread type. Possible types include
- Java thread: java thread
- Vmthread: internal thread of JVM
- CompilerThread: used to call JITing to compile and load class es in real time. Usually, the jvm will start multiple threads to handle this part of the work, and the number after the thread name will be accumulated, such as CompilerThread1
- GCTaskThread: thread executing gc
- WatcherThread: the thread of JVM periodic task scheduling, which is a singleton object
- ConcurrentMarkSweepThread: when the jvm performs CMS GC, it will create a thread to perform GC. When the thread is created, it will create a surrogatelocker thread (SLT) thread and start it. After SLT is started, it is in the waiting phase. When CMST starts GC, it will send a message to SLT to get the global Lock of the Java layer Reference object: Lock
- pool-1-thread-2: thread name
- _ thread_in_native: current thread state. The description also includes:
- _ thread_in_native: the current status of the thread. The status enumeration includes:
- _ thread_uninitialized: the thread has not been created yet. It only appears when memory crashes
- _ thread_new: the thread has been created but not started yet
- _ thread_in_native: the thread is executing local code. Generally, there is probably a problem with the local code
- _ thread_in_vm: thread executing virtual machine code
- _ thread_in_Java: the thread is executing interpreted or compiled Java code
- _ thread_blocked: the thread is blocked
- …_ Trans: in_ At the end of trans, the thread is in an intermediate state to switch to another state
- id=30111: thread ID
- stack(0x00007f3d567e5000,0x00007f3d568e6000): stack interval
siginfo: si_signo: 11 (SIGSEGV), si_code: 1 (SEGV_MAPERR), si_addr: 0x00000000000000031
Represents unexpected signal information that causes the virtual machine to terminate.
Top of Stack: (sp=0x00007f3d568e2280)0x00007f3d568e2280: b8e4bfb900000800 00007f3d568e37600x00007f3d568e2290: 00007f3d568e3758 00007f3d568e377c0x00007f3d568e22a0: 00007f3d568e3778 6f6e6b6e56a88a580x00007f3d568e22b0: 00000100000149a0 7a687108000000000x00007f3d568e22c0: 6970067363642d78 6d6f63036e61676e....ellipsis Instructions: (pc=0x0000003797807a91)0x0000003797807a71: 48 89 45 b8 48 8b 4d b8 0f b6 51 03 89 d3 83 e30x0000003797807a81: 0f 75 0d 0f b7 49 06 66 c1 c9 08 66 85 c9 75 4f0x0000003797807a91: 0f b6 48 03 bf 0f 00 00 00 40 20 cf 75 0d 0f b70x0000003797807aa1: 70 06 66 c1 ce 08 66 85 f6 75 34 83 e1 0f 83 e2 12345678910111213
The opcodes next to the program counter at the top of the stack, which can be compiled into instructions executed before the system crash.
Stack: [0x00007f3d567e5000,0x00007f3d568e6000], sp=0x00007f3d568e2280, free space=1012kNative frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)C [libresolv.so.2+0x7a91] __libc_res_nquery+0x1c1C [libresolv.so.2+0x7fd1]Java frames: (J=compiled Java code, j=interpreted, Vv=VM code)J 15056 java.net.Inet6AddressImpl.lookupAllHostAddr(Ljava/lang/String;)[Ljava/net/InetAddress; (0 bytes) @ 0x00007f3d7492af8c [0x00007f3d7492af40+0x4c]J 14966 C1 java.net.InetAddress.getAddressesFromNameService(Ljava/lang/String;Ljava/net/InetAddress;)[Ljava/net/InetAddress; (245 bytes) @ 0x00007f3d75466754 [0x00007f3d754662c0+0x494]J 14291 C2 java.net.InetAddress.getAllByName(Ljava/lang/String;Ljava/net/InetAddress;)[Ljava/net/InetAddress; (387 bytes) @ 0x00007f3d7534b718 [0x00007f3d7534ae20+0x8f8]J 14178 C1 java.net.InetSocketAddress.<init>(Ljava/lang/String;I)V (47 bytes) @ 0x00007f3d752ce0f4 [0x00007f3d752cdec0+0x234]j sun.security.ssl.SSLSocketImpl.<init>(Lsun/security/ssl/SSLContextImpl;Ljava/lang/String;ILjava/net/InetAddress;I)V+144j sun.security.ssl.SSLSocketFactoryImpl.createSocket(Ljava/lang/String;ILjava/net/InetAddress;I)Ljava/net/Socket;+13j com.ufclub.daq.qhzx.utils.SSLProtocolSocketFactory.createSocket(Ljava/lang/String;ILjava/net/InetAddress;I)Ljava/net/Socket;+15.... Omit code 123456789101121314
Thread stack information. It contains the address, top of stack, stack counter and stack information not used by the thread. By now, the cause of the problem has been basically determined.
Thread information
Java Threads: ( => current thread ) 0x00007f3d5d0a0800 JavaThread "logback-8" daemon [_thread_blocked, id=489, stack(0x00007f3d56de7000,0x00007f3d56ee8000)] 0x00007f3d5d09f800 JavaThread "logback-7" daemon [_thread_blocked, id=30974, stack(0x00007f3d53fc3000,0x00007f3d540c4000)] 0x00007f3d5c47f800 JavaThread "logback-6" daemon [_thread_blocked, id=25662, stack(0x00007f3d545c9000,0x00007f3d546ca000)] 0x00007f3d5c2a4000 JavaThread "logback-5" daemon [_thread_blocked, id=20922, stack(0x00007f3d552d2000,0x00007f3d553d3000)] 0x0000000003291800 JavaThread "logback-4" daemon [_thread_blocked, id=16768, stack(0x00007f3d542c6000,0x00007f3d543c7000)] 0x0000000002320000 JavaThread "logback-3" daemon [_thread_blocked, id=14730, stack(0x00007f3d54bcd000,0x00007f3d54cce000)] 0x0000000002d05000 JavaThread "logback-2" daemon [_thread_blocked, id=6569, stack(0x00007f3d549cb000,0x00007f3d54acc000)]12345678
All thread information is clear at a glance_ thread_blocked indicates blocking.
Safety point and lock information
VM state:not at safepoint (normal execution)1
Virtual machine status. not at safepoint indicates normal operation. Other states:
-at safepoint: all threads are blocked because of the virtual machine waiting state, waiting for a virtual machine operation to complete;
-Synchronization: a special virtual machine operation that requires other threads in the virtual machine to keep waiting.
VM Mutex/Monitor currently owned by a thread: None1
Mutex and Monito r of the virtual machine are not currently held by the thread. Mutex is a lock inside the virtual machine, while Monitor is associated with Java objects.
Heap information
Heap: PSYoungGen total 178688K, used 25522K [0x00000000eab00000, 0x00000000f8d80000, 0x0000000100000000) eden space 177664K, 13% used [0x00000000eab00000,0x00000000ec343d30,0x00000000f5880000) from space 1024K, 65% used [0x00000000f8c80000,0x00000000f8d28d20,0x00000000f8d80000) to space 1024K, 0% used [0x00000000f8b80000,0x00000000f8b80000,0x00000000f8c80000) ParOldGen total 360448K, used 47193K [0x00000000c0000000, 0x00000000d6000000, 0x00000000eab00000) object space 360448K, 13% used [0x00000000c0000000,0x00000000c2e16518,0x00000000d6000000) Metaspace used 79300K, capacity 80628K, committed 80936K, reserved 1120256K class space used 9401K, capacity 9645K, committed 9768K, reserved 1048576KCard table byte_map: [0x00007f3d729f1000,0x00007f3d72bf2000] byte_map_base: 0x00007f3d723f10001234567891011
The new generation, old age and meta space are clear at a glance.
Card table represents a card table. It is a data structure maintained by the jvm. It is used to record references when changing objects, so that fewer tables and root s can be traversed during gc.
Local code cache
CodeCache: size=245760Kb used=41374Kb max_used=41402Kb free=204385Kb bounds [0x00007f3d72fb2000, 0x00007f3d75872000, 0x00007f3d81fb2000] total_blobs=12767 nmethods=12130 adapters=549 compilation: enabled1234
A block of memory used to compile and store local code.
Compile event
Compilation events (10 events):Event: 501041.566 Thread 0x0000000001b6e000 16334 3 sun.security.rsa.RSAKeyFactory::<init> (5 bytes)Event: 501041.566 Thread 0x0000000001b6e000 nmethod 16334 0x00007f3d74985790 code [0x00007f3d74985900, 0x00007f3d74985b10]Event: 501041.569 Thread 0x0000000001b6e000 16335 3 sun.security.pkcs.PKCS8Key::<init> (5 bytes)Event: 501041.570 Thread 0x0000000001b6e000 nmethod 16335 0x00007f3d74736290 code [0x00007f3d74736400, 0x00007f3d747365b0]Event: 501041.575 Thread 0x0000000001b6e000 16336 3 sun.security.ssl.BaseSSLSocketImpl::<init> (15 bytes)Event: 501041.576 Thread 0x0000000001b6e000 nmethod 16336 0x00007f3d73f9b450 code [0x00007f3d73f9b5c0, 0x00007f3d73f9b7e8]Event: 501041.578 Thread 0x0000000001b6e000 16337 3 javax.net.ssl.SSLSocket::<init> (5 bytes)Event: 501041.580 Thread 0x0000000001b6e000 nmethod 16337 0x00007f3d739c7210 code [0x00007f3d739c7380, 0x00007f3d739c7508]Event: 501041.582 Thread 0x0000000001b6e000 16338 3 javax.net.ssl.SNIServerName::<init> (66 bytes)Event: 501041.583 Thread 0x0000000001b6e000 nmethod 16338 0x00007f3d74c15cd0 code [0x00007f3d74c15ea0, 0x00007f3d74c164f8]1234567891011
Record 10 compilation events. The information here also confirms the above conclusion.
gc log
GC Heap History (10 events):Event: 476166.948 GC heap before{Heap before GC invocations=149 (full 3): PSYoungGen total 194560K, used 193984K [0x00000000eab00000, 0x00000000f8e80000, 0x0000000100000000) eden space 193536K, 100% used [0x00000000eab00000,0x00000000f6800000,0x00000000f6800000) from space 1024K, 43% used [0x00000000f8c80000,0x00000000f8cf0000,0x00000000f8d80000) to space 1024K, 0% used [0x00000000f8d80000,0x00000000f8d80000,0x00000000f8e80000) ParOldGen total 360448K, used 47161K [0x00000000c0000000, 0x00000000d6000000, 0x00000000eab00000) object space 360448K, 13% used [0x00000000c0000000,0x00000000c2e0e518,0x00000000d6000000) Metaspace used 79243K, capacity 80500K, committed 80680K, reserved 1120256K class space used 9400K, capacity 9645K, committed 9768K, reserved 1048576KEvent: 476166.985 GC heap afterHeap after GC invocations=149 (full 3): PSYoungGen total 190464K, used 448K [0x00000000eab00000, 0x00000000f8e00000, 0x0000000100000000) eden space 189952K, 0% used [0x00000000eab00000,0x00000000eab00000,0x00000000f6480000) from space 512K, 87% used [0x00000000f8d80000,0x00000000f8df0000,0x00000000f8e00000) to space 1024K, 0% used [0x00000000f8c00000,0x00000000f8c00000,0x00000000f8d00000) ParOldGen total 360448K, used 47161K [0x00000000c0000000, 0x00000000d6000000, 0x00000000eab00000) object space 360448K, 13% used [0x00000000c0000000,0x00000000c2e0e518,0x00000000d6000000) Metaspace used 79243K, capacity 80500K, committed 80680K, reserved 1120256K class space used 9400K, capacity 9645K, committed 9768K, reserved 1048576K}... Omit 123456789101121314151617181920212223
Also record 10 GC s.
jvm memory mapping
Dynamic libraries:00400000-00401000 r-xp 00000000 fd:00 2108521 /usr/java/jdk1.8.0_45/bin/java00600000-00601000 rw-p 00000000 fd:00 2108521 /usr/java/jdk1.8.0_45/bin/java019e9000-04f5e000 rw-p 00000000 00:00 0 [heap]c0000000-d6000000 rw-p 00000000 00:00 0 d6000000-eab00000 ---p 00000000 00:00 0 ... 7f3d6df48000-7f3d6df6a000 r--s 0038e000 fd:00 2108900 /usr/java/jdk1.8.0_45/jre/lib/ext/cldrdata.jar7f3d6df6a000-7f3d6df73000 r--s 07db3000 fd:00 2374798 /opt/risk/service/xxx-xxx-container/xxx-xxxx-container.jar... 1234567891011
This information is the virtual memory list area when the virtual machine crashes. It can tell you which class libraries are being used, where they are, and stack and guard page information when you crash.
- 00400000-00401000: memory area
- r-xp: permission, r/w/x/p/s means read / write / execute / private / share respectively
- 00000000: offset within file
-
- fd:00: majorID and minorID of file location
- 2108521: inode number
- /usr/java/jdk1.8.0_45/bin/java: file location
From / opt / risk / service / xxx xxx container / xxx XXXX container Jar we can confirm that the jar has a problem.
jvm startup parameters
VM Arguments:jvm_args: -Xmx1024M -Xms512M -XX:PermSize=128M -XX:MaxPermSize=256M java_command: /opt/risk/service/xxx-xxx-xxx-container/xxx-xxx-xxx-container.jarjava_class_path (initial): /opt/risk/service/xxx-xxx-xxx-container/xxx-xxx-xxx-container.jarLauncher Type: SUN_STANDARDEnvironment Variables:JAVA_HOME=/usr/java/jdk1.8.0_45CLASSPATH=.:/usr/java/jdk1.8.0_45/lib/dt.jar:/usr/java/jdk1.8.0_45/lib/tools.jarPATH=/usr/java/jdk1.8.0_45/bin:/bin:/usr/local/erlang/bin:/usr/local/maven3/bin:/usr/local/git/bin:/usr/java/jdk1.8.0_45/bin:/bin:/usr/local/erlang/bin:/usr/local/maven3/bin:/usr/local/git/bin:/usr/lib64/qt-3.3/bin:/usr/local/sbin:/usr/bin:/bin:/usr/sbin:/sbin:/root/binSHELL=/bin/bash1234567891011
jvm virtual machine parameters and environment variables.