JVM致命錯(cuò)誤日志(hs_err_pid.log)分析
當(dāng)jvm出現(xiàn)致命錯(cuò)誤時(shí),會(huì)生成一個(gè)錯(cuò)誤文件 hs_err_pid<pid>.log,其中包括了導(dǎo)致jvm crash的重要信息,可以通過分析該文件定位到導(dǎo)致crash的根源,從而改善以保證系統(tǒng)穩(wěn)定。當(dāng)出現(xiàn)crash時(shí),該文件默認(rèn)會(huì)生成到工作目錄下,然 而可以通過jvm參數(shù)指定生成路徑(JDK6中引入):
-XX:ErrorFile=./hs_err_pid<pid>.log
該文件包含如下幾類關(guān)鍵信息:
-
日志頭文件
-
導(dǎo)致crash的線程信息
-
所有線程信息
-
安全點(diǎn)和鎖信息
-
堆信息
-
本地代碼緩存
-
編譯事件
-
gc相關(guān)記錄
-
jvm內(nèi)存映射
-
jvm啟動(dòng)參數(shù)
-
服務(wù)器信息
下面用一個(gè)crash demo文件逐步解讀這些信息,以便大家以后碰到crash時(shí)方便分析。
日志頭文件
日志頭文件包含概要信息,簡(jiǎn)述了導(dǎo)致crash的原因。而導(dǎo)致crash的原因很多,常見的原因有jvm自身的bug,應(yīng)用程序錯(cuò)誤,jvm參數(shù)配置不當(dāng),服務(wù)器資源不足,jni調(diào)用錯(cuò)誤等。
現(xiàn)在參考下如下描述:
- #
- # A fatal error has been detected by the Java Runtime Environment:
- #
- # SIGSEGV (0xb) at pc=0x00007fb8b18fdc6c, pid=191899, tid=140417770411776
- #
- # JRE version: Java(TM) SE Runtime Environment (7.0_55-b13) (build 1.7.0_55-b13)
- # Java VM: Java HotSpot(TM) 64-Bit Server VM (24.55-b03 mixed mode linux-amd64 compressed oops)
- # Problematic frame:
- # J org.apache.http.impl.cookie.BestMatchSpec.formatCookies(Ljava/util/List;)Ljava/util/List;
- #
- # 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.sun.com/bugreport/crash.jsp
- #
這里一個(gè)重要信息是“SIGSEGV(0xb)”表示jvm crash時(shí)正在執(zhí)行jni代碼,而不是在執(zhí)行java或者jvm的代碼,如果沒有在應(yīng)用程序里手動(dòng)調(diào)用jni代碼,那么很可能是JIT動(dòng)態(tài)編譯時(shí)導(dǎo)致的 該錯(cuò)誤。其中SIGSEGV是信號(hào)名稱,0xb是信號(hào)碼,pc=0x00007fb8b18fdc6c指的是程序計(jì)數(shù)器的值,pid=191899是進(jìn)程 號(hào),tid=140417770411776是線程號(hào)。
PS:除了“SIGSEGV(0xb)”以外,常見的描述還有“EXCEPTION_ACCESS_VIOLATION”,該描述表示jvm crash時(shí)正在執(zhí)行jvm自身的代碼,這往往是因?yàn)閖vm的bug導(dǎo)致的crash;另一種常見的描述是 “EXCEPTION_STACK_OVERFLOW”,該描述表示這是個(gè)棧溢出導(dǎo)致的錯(cuò)誤,這往往是應(yīng)用程序中存在深層遞歸導(dǎo)致的。
還有一個(gè)重要信息是:
# Problematic frame:
# J org.apache.http.impl.cookie.BestMatchSpec.formatCookies(Ljava/util/List;)Ljava/util/List;
這表示出現(xiàn)crash時(shí)jvm正在執(zhí)行的代碼,這里的“J”表示正在執(zhí)行java代碼,后面的表示執(zhí)行的方法棧。除了“J”外,還有可能是“C”、“j”、“V”、“v”,它們分別表示:
-
C: Native C frame
-
j: Interpreted Java frame
-
V: VMframe
-
v: VMgenerated stub frame
-
J: Other frame types, including compiled Java frames
加上前面對(duì)SIGSEGV(0xb)”的分析,現(xiàn)在可以斷定是JIT動(dòng)態(tài)編譯導(dǎo)致的該錯(cuò)誤。
查閱資料發(fā)現(xiàn):
此異常是由于jdk JIT compiler optimization 導(dǎo)致,bug id 8021898,官網(wǎng)描述如下:
The JIT compiler optimization leads to a SIGSEGV or an NullPointerException at a place it must not happen.
jdk1.7.0_25到1.7.0_55這幾個(gè)版本都存在此bug,1.7.0_60后修復(fù)。可通過升級(jí)jdk解決此異常,可參考 http://bugs.java.com/view_bug.do?bug_id=8021898。
到這里該問題已經(jīng)分析出原因了,但是咱們可以再深入一步,分析下其它信息。
導(dǎo)致crash的線程信息
文件下面是導(dǎo)致crash的線程信息和該線程棧信息,描述信息如下:
Current thread (0x00007fb7b4014800): JavaThread "catalina-exec-251" daemon [_thread_in_Java, id=205044, stack(0x00007fb58f435000,0x00007fb58f536000)]
siginfo:si_signo=SIGSEGV: si_errno=0, si_code=1 (SEGV_MAPERR), si_addr=0x0000003f96dc9c6c
以上表示導(dǎo)致出錯(cuò)的線程是0x00007fb7b4014800(指針),線程類型是JavaThread,JavaThread表示執(zhí)行的是java線程,關(guān)于該線程其它類型還可能是:
-
VMThread:jvm的內(nèi)部線程
-
CompilerThread:用來(lái)調(diào)用JITing,實(shí)時(shí)編譯裝卸class 。 通常,jvm會(huì)啟動(dòng)多個(gè)線程來(lái)處理這部分工作,線程名稱后面的數(shù)字也會(huì)累加,例如:CompilerThread1
-
GCTaskThread:執(zhí)行g(shù)c的線程
-
WatcherThread:jvm周期性任務(wù)調(diào)度的線程,是一個(gè)單例對(duì)象。 該線程在JVM內(nèi)使用得比較頻繁,比如:定期的內(nèi)存監(jiān)控、JVM運(yùn)行狀況監(jiān)控,還有我們經(jīng)常需要去執(zhí)行一些jstat 這類命令查看gc的情況
-
ConcurrentMarkSweepThread:jvm在進(jìn)行CMS GC的時(shí)候,會(huì)創(chuàng)建一個(gè)該線程去進(jìn)行GC,該線程被創(chuàng)建的同時(shí)會(huì)創(chuàng)建一個(gè)SurrogateLockerThread(簡(jiǎn)稱SLT)線程并且啟動(dòng) 它,SLT啟動(dòng)之后,處于等待階段。CMST開始GC時(shí),會(huì)發(fā)一個(gè)消息給SLT讓它去獲取Java層Reference對(duì)象的全局鎖:Lock
后面的”catalina-exec-251″表示線程名,帶有catalina前綴的線程一般是tomcat啟動(dòng)的線程,“daemon”表示該 線程為守護(hù)線程,再后面的“[_thread_in_Java”表示線程正在執(zhí)行解釋或者編譯后的Java代碼,關(guān)于該描述其它類型還可能是:
-
_thread_in_native:線程當(dāng)前狀態(tài)
-
_thread_uninitialized:線程還沒有創(chuàng)建,它只在內(nèi)存原因崩潰的時(shí)候才出現(xiàn)
-
_thread_new:線程已經(jīng)被創(chuàng)建,但是還沒有啟動(dòng)
-
_thread_in_native:線程正在執(zhí)行本地代碼,一般這種情況很可能是本地代碼有問題
-
_thread_in_vm:線程正在執(zhí)行虛擬機(jī)代碼
-
_thread_in_Java:線程正在執(zhí)行解釋或者編譯后的Java代碼
-
_thread_blocked:線程處于阻塞狀態(tài)
-
…_trans:以_trans結(jié)尾,線程正處于要切換到其它狀態(tài)的中間狀態(tài)
最后的“id=205044”表示線程ID,stack(0x00007fb58f435000,0x00007fb58f536000)表示棧區(qū)間。
“siginfo:si_signo=SIGSEGV: si_errno=0, si_code=1 (SEGV_MAPERR), si_addr=0x0000003f96dc9c6c”這部分是導(dǎo)致虛擬機(jī)終止的非預(yù)期的信號(hào)信息:其中si_errno和si_code是Linux 下用來(lái)鑒別異常的,Windows下是一個(gè)ExceptionCode。
所有線程信息
再下面是線程信息:
- Java Threads: ( => current thread )
- 0x00007fb798015800 JavaThread "catalina-exec-280" daemon [_thread_blocked, id=206093, stack(0x00007fb58d718000,0x00007fb58d819000)]
- 0x00007fb7a4016800 JavaThread ”catalina-exec-279″ daemon [_thread_blocked, id=206091, stack(0x00007fb58d819000,0x00007fb58d91a000)]
- … …(省略)
- Other Threads:
- 0x00007fb8b4231000 VMThread [stack: 0x00007fb854eb6000,0x00007fb854fb7000] [id=192015]
- 0x00007fb8b4321000 WatcherThread [stack: 0x00007fb835e6c000,0x00007fb835f6d000] [id=192414]
信息和上面介紹的類似,其中[_thread_blocked表示線程阻塞。
安全點(diǎn)和鎖信息
再下面是安全點(diǎn)和鎖信息:
VM state:not at safepoint (normal execution)
VM Mutex/Monitor currently owned by a thread: None
安全線信息為正常運(yùn)行,其它可能得描述還有:
-
not at a safepoint:正常運(yùn)行狀態(tài)
-
at safepoint:所有線程都因?yàn)樘摂M機(jī)等待狀態(tài)而阻塞,等待一個(gè)虛擬機(jī)操作完成
-
synchronizing:一個(gè)特殊的虛擬機(jī)操作,要求虛擬機(jī)內(nèi)的其它線程保持等待狀態(tài)
鎖信息為未被線程持有,Mutex是虛擬機(jī)內(nèi)部的鎖,而Monitor則是synchronized鎖或者其它關(guān)聯(lián)到的Java對(duì)象。
堆信息
再下面是堆信息:
- Heap
- par new generation total 2293760K, used 1537284K [0x00000006f0000000, 0x0000000790000000, 0x0000000790000000)
- eden space 1966080K, 78% used [0x00000006f0000000, 0x000000074dc97aa8, 0x0000000768000000)
- from space 327680K, 0% used [0x0000000768000000, 0x00000007680a9580, 0x000000077c000000)
- to space 327680K, 0% used [0x000000077c000000, 0x000000077c000000, 0x0000000790000000)
- concurrent mark-sweep generation total 1572864K, used 49449K [0x0000000790000000, 0x00000007f0000000, 0x00000007f0000000)
- concurrent-mark-sweep perm gen total 262144K, used 49857K [0x00000007f0000000, 0x0000000800000000, 0x0000000800000000)
- Card table byte_map: [0x00007fb8b8fa8000,0x00007fb8b9829000] byte_map_base: 0x00007fb8b5828000
堆信息包括:新生代、老生代、永久代信息。這里標(biāo)識(shí)了使用CMS垃圾收集器。
下面的“Card table”表示一種卡表,是jvm維護(hù)的一種數(shù)據(jù)結(jié)構(gòu),用于記錄更改對(duì)象時(shí)的引用,以便gc時(shí)遍歷更少的table和root。
本地代碼緩存
再下面是本地代碼緩存信息:
- Code Cache [0x00007fb8b1000000, 0x00007fb8b1a60000, 0x00007fb8b4000000)
- total_blobs=3580 nmethods=3111 adapters=421 free_code_cache=38857Kb largest_free_block=39469312
這是一塊用于編譯和保存本地代碼的內(nèi)存;注意是本地代碼,它和PermGen(永久代)是不一樣的,永久代是用來(lái)存放jvm和java類的元數(shù)據(jù)的。
編譯事件
再下面是本地代碼編譯信息:
- Compilation events (10 events):
- Event: 110587.798 Thread 0x00007fb8b425a800 3338 java.util.HashSet::remove (20 bytes)
- Event: 110587.804 Thread 0x00007fb8b425a800 nmethod 3338 0x00007fb8b168a9d0 code [0x00007fb8b168ab60, 0x00007fb8b168afa8]
- ... ...(省略)
- Event: 112147.387 Thread 0x00007fb8b425a800 3342 org.apache.http.impl.cookie.BestMatchSpec::formatCookies (116 bytes)
- Event: 112147.465 Thread 0x00007fb8b425a800 nmethod 3342 0x00007fb8b18fcd50 code [0x00007fb8b18fd1a0, 0x00007fb8b18ff338]
可以看到,一共編譯了10次;其中包含org.apache.http.impl.cookie.BestMatchSpec::formatCookies的編譯;這和前面的結(jié)論相吻合。
gc相關(guān)記錄
再下面是gc執(zhí)行記錄:
- GC Heap History (10 events):
- Event: 110665.975 GC heap before
- {Heap before GC invocations=255 (full 31):
- par new generation total 2293760K, used 1966777K [0x00000006f0000000, 0x0000000790000000, 0x0000000790000000)
- eden space 1966080K, 100% used [0x00000006f0000000, 0x0000000768000000, 0x0000000768000000)
- from space 327680K, 0% used [0x0000000768000000, 0x00000007680ae480, 0x000000077c000000)
- to space 327680K, 0% used [0x000000077c000000, 0x000000077c000000, 0x0000000790000000)
- concurrent mark-sweep generation total 1572864K, used 49237K [0x0000000790000000, 0x00000007f0000000, 0x00000007f0000000)
- concurrent-mark-sweep perm gen total 262144K, used 49856K [0x00000007f0000000, 0x0000000800000000, 0x0000000800000000)
- Event: 110665.981 GC heap after
- Heap after GC invocations=256 (full 31):
- par new generation total 2293760K, used 693K [0x00000006f0000000, 0x0000000790000000, 0x0000000790000000)
- eden space 1966080K, 0% used [0x00000006f0000000, 0x00000006f0000000, 0x0000000768000000)
- from space 327680K, 0% used [0x000000077c000000, 0x000000077c0ad6f8, 0x0000000790000000)
- to space 327680K, 0% used [0x0000000768000000, 0x0000000768000000, 0x000000077c000000)
- concurrent mark-sweep generation total 1572864K, used 49237K [0x0000000790000000, 0x00000007f0000000, 0x00000007f0000000)
- concurrent-mark-sweep perm gen total 262144K, used 49856K [0x00000007f0000000, 0x0000000800000000, 0x0000000800000000)
- }
- ... ...(省略)
可以看到gc次數(shù)為10次(full gc),然后后面描述了每次gc前后的內(nèi)存信息;看一看到并沒有內(nèi)存不足等問題。
jvm內(nèi)存映射
再下面是jvm加載的庫(kù)信息:
- Dynamic libraries:
- 00400000-00401000 r-xp 00000000 08:02 39454583 /home/service/jdk1.7.0_55/bin/java
- 00600000-00601000 rw-p 00000000 08:02 39454583 /home/service/jdk1.7.0_55/bin/java
- 013cd000-013ee000 rw-p 00000000 00:00 0 [heap]
- 6f0000000-800000000 rw-p 00000000 00:00 0
- 3056400000-3056416000 r-xp 00000000 08:02 57409539 /lib64/libgcc_s-4.4.7-20120601.so.1
- 3056416000-3056615000 ---p 00016000 08:02 57409539 /lib64/libgcc_s-4.4.7-20120601.so.1
- 3056615000-3056616000 rw-p 00015000 08:02 57409539 /lib64/libgcc_s-4.4.7-20120601.so.1
- 353be00000-353be20000 r-xp 00000000 08:02 57409933 /lib64/ld-2.12.so
- 353c01f000-353c020000 r--p 0001f000 08:02 57409933 /lib64/ld-2.12.so
- 353c020000-353c021000 rw-p 00020000 08:02 57409933 /lib64/ld-2.12.so
- ... ...(省略)
這些信息是虛擬機(jī)崩潰時(shí)的虛擬內(nèi)存列表區(qū)域。它可以告訴你崩潰原因時(shí)哪些類庫(kù)正在被使用,位置在哪里,還有堆棧和守護(hù)頁(yè)信息。以列表中第一條為例介紹下:
-
00400000-00401000:內(nèi)存區(qū)域
-
r-xp:權(quán)限,r/w/x/p/s分別表示讀/寫/執(zhí)行/私有/共享
-
00000000:文件內(nèi)的偏移量
-
08:02:文件位置的majorID和minorID
-
39454583:索引節(jié)點(diǎn)號(hào)
-
/home/service/jdk1.7.0_55/bin/java:文件位置
jvm啟動(dòng)參數(shù)
再下面是jvm啟動(dòng)參數(shù)信息:
- VM Arguments:
- jvm_args: -Djava.util.logging.config.file=/home/service/tomcat7007-account-web/conf/logging.properties -Xmx4096m -Xms4096m -Xmn2560m -XX:SurvivorRatio=6 -XX:PermSize=256m -XX:MaxPermSize=256m -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintGCDetails -Xloggc:/home/work/webdata/logs/tomcat7007-account-web/develop/gc.log -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/work/webdata/logs/tomcat7007-account-web/develop/ -Dtomcatlogdir=/home/work/webdata/logs/tomcat7007-account-web/develop -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=7407 -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false -Djava.endorsed.dirs=/home/service/tomcat7007-account-web/endorsed -Dcatalina.base=/home/service/tomcat7007-account-web -Dcatalina.home=/home/service/tomcat7007-account-web -Djava.io.tmpdir=/home/service/tomcat7007-account-web/temp
- java_command: org.apache.catalina.startup.Bootstrap start
- Launcher Type: SUN_STANDARD
- Environment Variables:
- JAVA_HOME=/home/service/jdk1.7.0_55
- PATH=/opt/zabbix/bin:/opt/zabbix/sbin:/home/service/jdk1.7.0_55/bin:/home/work/bin:/usr/local/bin:/bin:/usr/bin:/usr/local/sbin:/usr/sbin:/sbin:/home/work/bin
- SHELL=/bin/bash
上面是jvm參數(shù),下面是系統(tǒng)的環(huán)境配置。
服務(wù)器信息
再下面是服務(wù)器信息:
- /proc/meminfo:
- MemTotal: 65916492 kB
- MemFree: 14593468 kB
- Buffers: 222452 kB
- Cached: 28502452 kB
- SwapTotal: 0 kB
- SwapFree: 0 kB
- ... ...(省略)
- /proc/cpuinfo:
- processor : 0
- vendor_id : GenuineIntel
- cpu family : 6
- model : 62
- model name : Intel(R) Xeon(R) CPU E5-2420 v2 @ 2.20GHz
- stepping : 4
- ... ...(省略)
上面是內(nèi)存信息,主要關(guān)注下swap信息,看看有沒有使用虛擬內(nèi)存;下面是cpu信息。