JVM致命錯誤日誌(hs_err_pid.log)分析
當jvm出現致命錯誤時,會生成一個錯誤檔案 hs_err_pid<pid>.log,其中包括了導致jvm crash的重要資訊,可以通過分析該檔案定位到導致crash的根源,從而改善以保證系統穩定。當出現crash時,該檔案預設會生成到工作目錄下,然而可以通過jvm引數指定生成路徑(JDK6中引入):
-XX:ErrorFile=./hs_err_pid<pid>.log
該檔案包含如下幾類關鍵資訊:
- 日誌標頭檔案
- 導致crash的執行緒資訊
- 所有執行緒資訊
- 安全點和鎖資訊
- 堆資訊
- 原生程式碼快取
- 編譯事件
- gc相關記錄
- jvm記憶體對映
- jvm啟動引數
- 伺服器資訊
下面用一個crash demo檔案逐步解讀這些資訊,以便大家以後碰到crash時方便分析。
日誌標頭檔案
日誌標頭檔案包含概要資訊,簡述了導致crash的原因。而導致crash的原因很多,常見的原因有jvm自身的bug,應用程式錯誤,jvm引數配置不當,伺服器資源不足,jni呼叫錯誤等。
現在參考下如下描述:
# # 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 #
這裡一個重要資訊是“SIGSEGV(0xb)”表示jvm crash時正在執行jni程式碼,而不是在執行java或者jvm的程式碼,如果沒有在應用程式裡手動呼叫jni程式碼,那麼很可能是JIT動態編譯時導致的該錯誤。其中SIGSEGV是訊號名稱,0xb是訊號碼,pc=0x00007fb8b18fdc6c指的是程式計數器的值,pid=191899是程式號,tid=140417770411776是執行緒號。
PS:除了“SIGSEGV(0xb)”以外,常見的描述還有“EXCEPTION_ACCESS_VIOLATION”,該描述表示jvm crash時正在執行jvm自身的程式碼,這往往是因為jvm的bug導致的crash;另一種常見的描述是“EXCEPTION_STACK_OVERFLOW”,該描述表示這是個棧溢位導致的錯誤,這往往是應用程式中存在深層遞迴導致的。
還有一個重要資訊是:
# Problematic frame:
# J org.apache.http.impl.cookie.BestMatchSpec.formatCookies(Ljava/util/List;)Ljava/util/List;
這表示出現crash時jvm正在執行的程式碼,這裡的“J”表示正在執行java程式碼,後面的表示執行的方法棧。除了“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
加上前面對SIGSEGV(0xb)”的分析,現在可以斷定是JIT動態編譯導致的該錯誤。
查閱資料發現:
此異常是由於jdk JIT compiler optimization 導致,bug id 8021898,官網描述如下:
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這幾個版本都存在此bug,1.7.0_60後修復。可通過升級jdk解決此異常,可參考 http://bugs.java.com/view_bug.do?bug_id=8021898。
到這裡該問題已經分析出原因了,但是我們們可以再深入一步,分析下其它資訊。
導致crash的執行緒資訊
檔案下面是導致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
以上表示導致出錯的執行緒是0x00007fb7b4014800(指標),執行緒型別是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
後面的”catalina-exec-251″表示執行緒名,帶有catalina字首的執行緒一般是tomcat啟動的執行緒,“daemon”表示該執行緒為守護執行緒,再後面的“[_thread_in_Java”表示執行緒正在執行解釋或者編譯後的Java程式碼,關於該描述其它型別還可能是:
- _thread_in_native:執行緒當前狀態
- _thread_uninitialized:執行緒還沒有建立,它只在記憶體原因崩潰的時候才出現
- _thread_new:執行緒已經被建立,但是還沒有啟動
- _thread_in_native:執行緒正在執行原生程式碼,一般這種情況很可能是原生程式碼有問題
- _thread_in_vm:執行緒正在執行虛擬機器程式碼
- _thread_in_Java:執行緒正在執行解釋或者編譯後的Java程式碼
- _thread_blocked:執行緒處於阻塞狀態
- …_trans:以_trans結尾,執行緒正處於要切換到其它狀態的中間狀態
最後的“id=205044”表示執行緒ID,stack(0x00007fb58f435000,0x00007fb58f536000)表示棧區間。
“siginfo:si_signo=SIGSEGV: si_errno=0, si_code=1 (SEGV_MAPERR), si_addr=0x0000003f96dc9c6c”這部分是導致虛擬機器終止的非預期的訊號資訊:其中si_errno和si_code是Linux下用來鑑別異常的,Windows下是一個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表示執行緒阻塞。
安全點和鎖資訊
再下面是安全點和鎖資訊:
VM state:not at safepoint (normal execution) VM Mutex/Monitor currently owned by a thread: None
安全線資訊為正常執行,其它可能得描述還有:
- not at a safepoint:正常執行狀態
- at safepoint:所有執行緒都因為虛擬機器等待狀態而阻塞,等待一個虛擬機器操作完成
- synchronizing:一個特殊的虛擬機器操作,要求虛擬機器內的其它執行緒保持等待狀態
鎖資訊為未被執行緒持有,Mutex是虛擬機器內部的鎖,而Monitor則是synchronized鎖或者其它關聯到的Java物件。
堆資訊
再下面是堆資訊:
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
堆資訊包括:新生代、老生代、永久代資訊。這裡標識了使用CMS垃圾收集器。
下面的“Card table”表示一種卡表,是jvm維護的一種資料結構,用於記錄更改物件時的引用,以便gc時遍歷更少的table和root。
原生程式碼快取
再下面是原生程式碼快取資訊:
Code Cache [0x00007fb8b1000000, 0x00007fb8b1a60000, 0x00007fb8b4000000) total_blobs=3580 nmethods=3111 adapters=421 free_code_cache=38857Kb largest_free_block=39469312
這是一塊用於編譯和儲存原生程式碼的記憶體;注意是原生程式碼,它和PermGen(永久代)是不一樣的,永久代是用來存放jvm和java類的後設資料的。
編譯事件
再下面是原生程式碼編譯資訊:
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的編譯;這和前面的結論相吻合。
gc相關記錄
再下面是gc執行記錄:
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次數為10次(full gc),然後後面描述了每次gc前後的記憶體資訊;看一看到並沒有記憶體不足等問題。
jvm記憶體對映
再下面是jvm載入的庫資訊:
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 ... ...(省略)
這些資訊是虛擬機器崩潰時的虛擬記憶體列表區域。它可以告訴你崩潰原因時哪些類庫正在被使用,位置在哪裡,還有堆疊和守護頁資訊。以列表中第一條為例介紹下:
- 00400000-00401000:記憶體區域
- r-xp:許可權,r/w/x/p/s分別表示讀/寫/執行/私有/共享
- 00000000:檔案內的偏移量
- 08:02:檔案位置的majorID和minorID
- 39454583:索引節點號
- /home/service/jdk1.7.0_55/bin/java:檔案位置
jvm啟動引數
再下面是jvm啟動引數資訊:
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引數,下面是系統的環境配置。
伺服器資訊
再下面是伺服器資訊:
/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 ... ...(省略)
上面是記憶體資訊,主要關注下swap資訊,看看有沒有使用虛擬記憶體;下面是cpu資訊。
相關文章
- JVM致命錯誤日誌(hs_err_pid.log)解讀JVM
- net 日誌分析錯誤
- mysql 日誌之錯誤日誌MySql
- 排查錯誤日誌
- mysql慢查詢和錯誤日誌分析MySql
- Apche日誌系列(2):錯誤日誌(轉)
- alert日誌中的兩種ORA錯誤分析
- Mabatis配置錯誤日誌BAT
- 日誌查詢錯誤
- 錯誤日誌檢視
- SQL Server 錯誤日誌SQLServer
- 如何用NodeJS讀取分析Nginx錯誤日誌NodeJSNginx
- log4j不輸出日誌錯誤分析
- MySQL 狂寫錯誤日誌MySql
- jdon框架日誌資訊錯誤框架
- SAP 錯誤日誌的調查
- node錯誤處理與日誌
- 上一個日誌的錯誤
- Sqlserver:代理錯誤日誌,知多少?SQLServer
- SQL Server ErrorLog 錯誤日誌SQLServerError
- aix ip 衝突錯誤日誌AI
- oracle日誌錯誤恢復(轉)Oracle
- insert中啟用錯誤日誌的問題及分析
- mysql之 日誌體系(錯誤日誌、查詢日誌、二進位制日誌、事務日誌、中繼日誌)MySql中繼
- 【問題解決】win10日誌錯誤:建立 TLS 客戶端憑據時發生致命錯誤。 內部錯誤狀態為 10013Win10TLS客戶端
- 開啟PHP的錯誤log日誌PHP
- 常見的錯誤日誌型別型別
- 日誌分析-apache日誌分析Apache
- JVM GC日誌解析JVMGC
- JVM的GC日誌JVMGC
- Mysql5.7 的錯誤日誌中最常見的note日誌MySql
- MySQL資料庫中的日誌檔案---(1)錯誤日誌MySql資料庫
- Kubelet 錯誤日誌 broken pipe 和 connection reset by peer 的原因分析
- 通過JVM日誌來進行安全點分析JVM
- ITMySQL錯誤日誌與通用查詢日誌圖文詳析jugMySql
- node專案錯誤處理與日誌
- 2、MySQL錯誤日誌(Error Log)詳解MySqlError
- Oracle10g DML錯誤日誌表Oracle