2. 程式人生 > 實用技巧 >JVM致命錯誤日誌(hs_err_pid.log)分析

JVM致命錯誤日誌(hs_err_pid.log)分析

阿新 • • 發佈：2020-12-16

當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呼叫錯誤等。

現在參考下如下描述：

#
#AfatalerrorhasbeendetectedbytheJavaRuntimeEnvironment:
#
#SIGSEGV(0xb)atpc=0x00007fb8b18fdc6c,pid=191899,tid=140417770411776
#
#JREversion:Java(TM)SERuntimeEnvironment(7.0_55-b13)(build1.7.0_55-b13)
#JavaVM:JavaHotSpot(TM)64-BitServerVM(24.55-b03mixedmodelinux-amd64compressedoops)
#Problematicframe:
#Jorg.apache.http.impl.cookie.BestMatchSpec.formatCookies(Ljava/util/List;)Ljava/util/List;
#
#Failedtowritecoredump.Coredumpshavebeendisabled.Toenablecoredumping,try"ulimit-cunlimited"beforestartingJavaagain
#
#Ifyouwouldliketosubmitabugreport,pleasevisit:
#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，官網描述如下：

TheJITcompileroptimizationleadstoaSIGSEGVoranNullPointerExceptionataplaceitmustnothappen.

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的執行緒資訊和該執行緒棧資訊，描述資訊如下：

Currentthread(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。

所有執行緒資訊

再下面是執行緒資訊：

JavaThreads:(=>currentthread)
0x00007fb798015800JavaThread"catalina-exec-280"daemon[_thread_blocked,id=206093,stack(0x00007fb58d718000,0x00007fb58d819000)]
0x00007fb7a4016800JavaThread"catalina-exec-279"daemon[_thread_blocked,id=206091,stack(0x00007fb58d819000,0x00007fb58d91a000)]
......(省略)

OtherThreads:
0x00007fb8b4231000VMThread[stack:0x00007fb854eb6000,0x00007fb854fb7000][id=192015]
0x00007fb8b4321000WatcherThread[stack:0x00007fb835e6c000,0x00007fb835f6d000][id=192414]

資訊和上面介紹的類似，其中[_thread_blocked表示執行緒阻塞。

安全點和鎖資訊

再下面是安全點和鎖資訊：

VMstate:notatsafepoint(normalexecution)

VMMutex/Monitorcurrentlyownedbyathread:None

安全線資訊為正常執行，其它可能得描述還有：

  • not at a safepoint：正常執行狀態

  • at safepoint：所有執行緒都因為虛擬機器等待狀態而阻塞，等待一個虛擬機器操作完成

  • synchronizing：一個特殊的虛擬機器操作，要求虛擬機器內的其它執行緒保持等待狀態

鎖資訊為未被執行緒持有，Mutex是虛擬機器內部的鎖，而Monitor則是synchronized鎖或者其它關聯到的Java物件。

堆資訊

再下面是堆資訊：

Heap
parnewgenerationtotal2293760K,used1537284K[0x00000006f0000000,0x0000000790000000,0x0000000790000000)
edenspace1966080K,78%used[0x00000006f0000000,0x000000074dc97aa8,0x0000000768000000)
fromspace327680K,0%used[0x0000000768000000,0x00000007680a9580,0x000000077c000000)
tospace327680K,0%used[0x000000077c000000,0x000000077c000000,0x0000000790000000)
concurrentmark-sweepgenerationtotal1572864K,used49449K[0x0000000790000000,0x00000007f0000000,0x00000007f0000000)
concurrent-mark-sweeppermgentotal262144K,used49857K[0x00000007f0000000,0x0000000800000000,0x0000000800000000)

Cardtablebyte_map:[0x00007fb8b8fa8000,0x00007fb8b9829000]byte_map_base:0x00007fb8b5828000

堆資訊包括：新生代、老生代、永久代資訊。這裡標識了使用CMS垃圾收集器。

下面的“Card table”表示一種卡表，是jvm維護的一種資料結構，用於記錄更改物件時的引用，以便gc時遍歷更少的table和root。

原生代碼快取

再下面是原生代碼快取資訊：

CodeCache[0x00007fb8b1000000,0x00007fb8b1a60000,0x00007fb8b4000000)
total_blobs=3580nmethods=3111adapters=421free_code_cache=38857Kblargest_free_block=39469312

這是一塊用於編譯和儲存原生代碼的記憶體；注意是原生代碼，它和PermGen（永久代）是不一樣的，永久代是用來存放jvm和java類的元資料的。

編譯事件

再下面是原生代碼編譯資訊：

Compilationevents(10events):
Event:110587.798Thread0x00007fb8b425a8003338java.util.HashSet::remove(20bytes)
Event:110587.804Thread0x00007fb8b425a800nmethod33380x00007fb8b168a9d0code[0x00007fb8b168ab60,0x00007fb8b168afa8]
......（省略）
Event:112147.387Thread0x00007fb8b425a8003342org.apache.http.impl.cookie.BestMatchSpec::formatCookies(116bytes)
Event:112147.465Thread0x00007fb8b425a800nmethod33420x00007fb8b18fcd50code[0x00007fb8b18fd1a0,0x00007fb8b18ff338]

可以看到，一共編譯了10次；其中包含org.apache.http.impl.cookie.BestMatchSpec::formatCookies的編譯；這和前面的結論相吻合。

gc相關記錄

再下面是gc執行記錄：

GCHeapHistory(10events):
Event:110665.975GCheapbefore
{HeapbeforeGCinvocations=255(full31):
parnewgenerationtotal2293760K,used1966777K[0x00000006f0000000,0x0000000790000000,0x0000000790000000)
edenspace1966080K,100%used[0x00000006f0000000,0x0000000768000000,0x0000000768000000)
fromspace327680K,0%used[0x0000000768000000,0x00000007680ae480,0x000000077c000000)
tospace327680K,0%used[0x000000077c000000,0x000000077c000000,0x0000000790000000)
concurrentmark-sweepgenerationtotal1572864K,used49237K[0x0000000790000000,0x00000007f0000000,0x00000007f0000000)
concurrent-mark-sweeppermgentotal262144K,used49856K[0x00000007f0000000,0x0000000800000000,0x0000000800000000)
Event:110665.981GCheapafter
HeapafterGCinvocations=256(full31):
parnewgenerationtotal2293760K,used693K[0x00000006f0000000,0x0000000790000000,0x0000000790000000)
edenspace1966080K,0%used[0x00000006f0000000,0x00000006f0000000,0x0000000768000000)
fromspace327680K,0%used[0x000000077c000000,0x000000077c0ad6f8,0x0000000790000000)
tospace327680K,0%used[0x0000000768000000,0x0000000768000000,0x000000077c000000)
concurrentmark-sweepgenerationtotal1572864K,used49237K[0x0000000790000000,0x00000007f0000000,0x00000007f0000000)
concurrent-mark-sweeppermgentotal262144K,used49856K[0x00000007f0000000,0x0000000800000000,0x0000000800000000)
}
......（省略）

可以看到gc次數為10次（full gc），然後後面描述了每次gc前後的記憶體資訊；看一看到並沒有記憶體不足等問題。

jvm記憶體對映

再下面是jvm載入的庫資訊：

Dynamiclibraries:
00400000-00401000r-xp0000000008:0239454583/home/service/jdk1.7.0_55/bin/java
00600000-00601000rw-p0000000008:0239454583/home/service/jdk1.7.0_55/bin/java
013cd000-013ee000rw-p0000000000:000[heap]
6f0000000-800000000rw-p0000000000:000
3056400000-3056416000r-xp0000000008:0257409539/lib64/libgcc_s-4.4.7-20120601.so.1
3056416000-3056615000---p0001600008:0257409539/lib64/libgcc_s-4.4.7-20120601.so.1
3056615000-3056616000rw-p0001500008:0257409539/lib64/libgcc_s-4.4.7-20120601.so.1
353be00000-353be20000r-xp0000000008:0257409933/lib64/ld-2.12.so
353c01f000-353c020000r--p0001f00008:0257409933/lib64/ld-2.12.so
353c020000-353c021000rw-p0002000008:0257409933/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啟動引數資訊：

VMArguments:
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.Bootstrapstart
LauncherType:SUN_STANDARD

EnvironmentVariables:
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:65916492kB
MemFree:14593468kB
Buffers:222452kB
Cached:28502452kB
SwapTotal:0kB
SwapFree:0kB
......（省略）
/proc/cpuinfo:
processor	:0
vendor_id	:GenuineIntel
cpufamily	:6
model		:62
modelname	:Intel(R)Xeon(R)CPUE5-2420v2@2.20GHz
stepping	:4
......（省略）

上面是記憶體資訊，主要關注下swap資訊，看看有沒有使用虛擬記憶體；下面是cpu資訊。

本文轉自：https://my.oschina.net/xionghui/blog/498785

相關推薦

JVM致命錯誤日誌(hs_err_pid.log)分析

當jvm出現致命錯誤時，會生成一個錯誤檔案hs_err_pid<pid>.log，其中包括了導致jvm crash的重要資訊，可以通過分析該檔案定位到導致crash的根源，從而改善以保證系統穩定。當出現crash時，該檔案預設會生成到工

JVM致命錯誤日誌（hs_err_pid.log）解讀

致命錯誤出現的時候，JVM生成了hs_err_pid <pid> .log這樣的檔案，其中經常包含了虛擬機器崩潰原因的重要資訊。因為經常遇到，在介紹文章裡，我選擇了一個，並且逐段分析情況包含的內容（檔案可以在文章最後下

JVM優化GC日誌分析-GC Easy工具

　　JVM優化在一些小專案中很少設定，一般都是設定一些堆疊大小就可以了，但是專案比較大的時候，一些無用的物件比較多，這個時候需要檢視GC日誌進行分析，如果單純的看看日誌的話，就不是很直觀了，就需要工具的幫忙

MySQL錯誤日誌（Error Log）

錯誤日誌是一個文字檔案，記錄了 MySQL Server 每次啟動和關閉的詳細資訊以及執行過程中所有較為嚴重的警告和錯誤資訊。在遇到問題時，應該首先檢視這個檔案。

MySQL錯誤日誌（Error Log）詳解

錯誤日誌（Error Log）是 MySQL 中最常用的一種日誌，主要記錄 MySQL 伺服器啟動和停止過程中的資訊、伺服器在執行過程中發生的故障和異常情況等。作為初學者，要學會利用錯誤日誌來定位問題。下面介紹如何操作檢視

解析php效能分析之php-fpm慢執行日誌slow log用法

本文例項講述了php效能分析之php-fpm慢執行日誌slow log用法。分享給大家供大家參考，具體如下：

（乾貨篇）GC日誌逐行分析+關鍵效能優化引數分析

前言 最近遇到幾個系統 young gc 時間比較長，在 young gc 長的同時，系統負載也隨時升高，因此熟讀GC日誌以及瞭解一些Jvm常見調優是必要的。

SQL Server(MSSQLSERVER) 請求失敗或服務未及時響應，有關詳細資訊，請參見事件日誌或其他的適用的錯誤日誌。

轉自：www.fengjunzi.com/blog-25573.… 問題 有時候sqlserver無法啟動了，原因是mssqlserver服務沒有啟動，當你手動啟動時，又出現服務無法響應的可惡錯誤提示。。。

Redis連線錯誤的情況總結分析

前言 最近由於流量增大，redis 出現了一連串錯誤，比如： LOADING Redis is loading the dataset in memory

sql server中錯誤日誌errorlog的深入講解

一 .概述 SQL Server 將某些系統事件和使用者定義事件記錄到 SQL Server 錯誤日誌和 Microsoft Windows 應用程式日誌中。 這兩種日誌都會自動給所有記錄事件加上時間戳。 使用 SQL Server 錯誤日誌中的資訊可以解決S

詳解grep獲取MySQL錯誤日誌資訊的方法

為方便維護MySQL，寫了個指令碼用以提供收集錯誤資訊的介面。這些錯誤資訊來自與MySQL錯誤日誌，而 通過grep mysql可以獲取error-log的路徑。

MongoDB資料庫的日誌檔案深入分析

前言 日誌是MongoDB中一個非常重要的功能,他保證了資料庫伺服器在意外斷電、自然災害下資料的完整性 。MongoDB日誌記錄了資料庫例項的健康狀態、語句的執行狀況、資源的消耗情況，所以日誌對於分析資料庫服務和效能優

python自動化測試之異常及日誌操作例項分析

本文例項講述了python自動化測試之異常及日誌操作。分享給大家供大家參考，具體如下：

android studio列印日誌語句Log.d()詳解

Log.d()方法內需要傳入兩個引數。 1.第一個引數時tag，一般傳入類名，用於對列印資訊進行過濾；

Win10電腦玩使命召喚16致命錯誤Disc read error怎麼辦

有win10正式版系統使用者在電腦中玩使命召喚16遊戲的時候，出現了致命錯誤：單人劇情進去沒有著色器安裝進度條，設定了麵點擊重新安裝以後到70%彈出致命錯誤，提示：Disc read error [5.0]: techsets safehouse fina

Win10安裝Virtualbox提示“安裝失敗！ 錯誤：安裝訊息期間發生致命錯誤”怎麼辦

VirtualBox 是一款開源虛擬機器軟體，體積小，執行時不會佔用太多記憶體空間，贏得許多小夥伴喜愛。而且VirtualBox是允許使用者將Win10作為主機執行，雖然安裝步驟簡單，但難免出現一些問題，有的使用者遇到Win10安裝

乾貨分享丨jvm系列：dump檔案深度分析

摘要：java記憶體dump是jvm執行時記憶體的一份快照，利用它可以分析是否存在記憶體浪費，可以檢查記憶體管理是否合理，當發生OOM的時候，可以找出問題的原因。那麼dump檔案的內容是什麼樣的呢？

【k8s】etcd叢集took too long to execute慢日誌告警問題分析

背景 目前機器學習平臺後端採用k8s架構進行GPU和CPU資源的排程和容器編排。總所周知，k8s的後端核心儲存使用etcd進行metadata持久化儲存。機器學習平臺採取[External etcd topology](http://way.xiaojukeji.com/art

linux日誌朔源分析記錄

lastlog 記錄使用者最後一次登入情況 只有root最近登入過 lastlog -u 使用者名稱或者uid

DjangoRestFrameWork整合sentry錯誤日誌伺服器

sentry簡介 Sentry 是一個開源的實時錯誤追蹤系統，可以幫助開發者實時監控並修復異常問題。它主要專注於持續整合、提高效率並且提升使用者體驗。Sentry 分為服務端和客戶端 SDK，前者可以直接使用它家提供的線上