JVM致命錯誤日誌(hs_err_pid.log)分析（轉載）

時間  2019-11-10
標籤 jvm 致命 錯誤 日誌 err pid.log pid log 分析 轉載 欄目 Java 简体版
原文   原文鏈接

當jvm出現致命錯誤時，會生成一個錯誤文件 hs_err_pid<pid>.log，其中包括了致使jvm crash的重要信息，能夠經過分析該文件定位到致使crash的根源，從而改善以保證系統穩定。當出現crash時，該文件默認會生成到工做目錄下，然而能夠經過jvm參數指定生成路徑（JDK6中引入）：java

-XX:ErrorFile=./hs_err_pid<pid>.log

該文件包含以下幾類關鍵信息：linux

  • 日誌頭文件
  • 致使crash的線程信息
  • 全部線程信息
  • 安全點和鎖信息
  • 堆信息
  • 本地代碼緩存
  • 編譯事件
  • gc相關記錄
  • jvm內存映射
  • jvm啓動參數
  • 服務器信息

下面用一個crash demo文件逐步解讀這些信息，以便你們之後碰到crash時方便分析。web

日誌頭文件

日誌頭文件包含概要信息，簡述了致使crash的緣由。而致使crash的緣由不少，常見的緣由有jvm自身的bug，應用程序錯誤，jvm參數配置不當，服務器資源不足，jni調用錯誤等。apache

如今參考下以下描述：緩存

#
# 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是線程號。tomcat

PS：除了「SIGSEGV(0xb)」之外，常見的描述還有「EXCEPTION_ACCESS_VIOLATION」，該描述表示jvm crash時正在執行jvm自身的代碼，這每每是由於jvm的bug致使的crash；另外一種常見的描述是「EXCEPTION_STACK_OVERFLOW」，該描述表示這是個棧溢出致使的錯誤，這每每是應用程序中存在深層遞歸致使的。安全

還有一個重要信息是：bash

# Problematic frame:服務器

# J org.apache.http.impl.cookie.BestMatchSpec.formatCookies(Ljava/util/List;)Ljava/util/List;cookie

這表示出現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信息。

相關文章
相關標籤/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公眾號
   歡迎關注本站公眾號,獲取更多信息
聯繫我們 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程