[toc] 這篇文章是我之前總結的一篇文章,因為整理博客的原因,原有博客已經註銷,但這篇文章對一些讀者很有用,所以現在新瓶裝舊酒重新整理回來分享給大家。 最近一段時間生產環境頻繁出問題,每次都會生成一個hs_err_pid*.log文件,因為工作內容的原因,在此之前並沒有瞭解過相關內容,趁此機會學習 ...
目錄
這篇文章是我之前總結的一篇文章,因為整理博客的原因,原有博客已經註銷,但這篇文章對一些讀者很有用,所以現在新瓶裝舊酒重新整理回來分享給大家。
最近一段時間生產環境頻繁出問題,每次都會生成一個hs_err_pid*.log文件,因為工作內容的原因,在此之前並沒有瞭解過相關內容,趁此機會學習下,根據項目的使用情況,此文章針對JDK 8進行分析,不過因為素材問題,文章中引用的文件內容為JDK 7生成的文件,此處應該不影響,因為官方文檔中關於此部分說明使用的是JDK 6生成的文件。我們將按照內容在文件中出現的順序進行介紹。本人水平有限,工作中也沒有太多機會進行此類知識的應用,文章內容主要參考官方文檔,某些內容在官方文檔中並沒有涉及,相應的介紹也不一定准確,如果有不同看法可在評論區留言交流。
PS:本人水平有限,工作中也沒有太多機會進行此類知識的應用,文章內容絕大多數來自於官方文檔,某些內容在官網中並沒有涉及,相應的介紹不一定准確,希望各位大佬不吝賜教
JDK 8
官方文檔下載地址:https://www.oracle.com/java/technologies/javase-jdk8-doc-downloads.html
致命錯誤日誌文檔:/docs/technotes/guides/troubleshoot/felog.html#fatal_error_log_vm
JDK 7
官方文檔地址:https://docs.oracle.com/javase/7/docs/
致命錯誤日誌文檔:https://docs.oracle.com/javase/7/docs/webnotes/tsg/TSG-VM/html/felog.html
文件描述
錯誤日誌是在JVM遇到致命錯誤時生成的日誌文件,可能包括以下信息:
- 引發致命錯誤的異常操作或信號
- 版本和配置信息
- 引發致命錯誤的線程詳細信息和線程堆棧記錄
- 正在運行的線程及其狀態的列表
- 有關堆的概要信息
- 載入的本機庫的列表
- 命令行參數
- 環境變數
- 操作系統和 CPU 的詳細信息
當問題嚴重到錯誤處理器無法收集並報告所有信息時,可能只有一部分信息會寫入錯誤日誌。
文件總共分為一下幾個章節:
- 簡單描述崩潰信息的文件頭
- 線程描述部分
- 進程描述部分
- 系統信息部分
文件位置
致命錯誤日誌文件位置可以通過 -XX:ErrorFile
進行指定,例如:
java * -XX:ErrorFile=/var/log/java/java_error%p.log
以上設置表示文件會放在/var/log/java
目錄下,%p
表示進程的PID。如果不設置XX:ErrorFile
屬性,日誌預設生成在執行java命令的目錄下,文件名預設為hs_err_pid%p.log
,如果該目錄因為某種情況無法寫入(空間不足,許可權不足等),在linux系統下預設寫到/tmp
目錄下,windows系統下預設使用環境變數中TMP
對應的目錄,如果沒有則使用TEMP
對應的目錄(TMP和TEMP均為windows預設的環境變數,且預設值一樣)。
文件頭
文件頭在錯誤日誌的最開頭,主要是對問題的簡單描述。這部分內容同樣會列印到標準輸出,可能也會列印到應用程式的控制臺上。示例如下:
#
# A fatal error has been detected by the Java Runtime Environment:
#
# SIGSEGV (0xb) at pc=0x00007f80e0cd095c, pid=48, tid=140189843019520
#
# JRE version: Java(TM) SE Runtime Environment (7.0_80-b15) (build 1.7.0_80-b15)
# Java VM: Java HotSpot(TM) 64-Bit Server VM (24.80-b11 mixed mode linux-amd64 compressed oops)
# Problematic frame:
# V [libjvm.so+0x65395c] jni_SetByteArrayRegion+0x19c
#
# Core dump written. Default location: /apps/gateway/project/bin/core or core.48
#
# If you would like to submit a bug report, please visit:
# http://bugreport.java.com/bugreport/crash.jsp
#
錯誤信息記錄
前兩行主要描述了信號類型、發起信號的程式計數器、進程ID和線程ID,對應關係如下所示,鑒於瀏覽器和手機端顯示效果不一致,此處提供兩種方式:
# SIGSEGV (0xb) at pc=0x00007f80e0cd095c, pid=48, tid=140189843019520
| | | | |
| | | | +--- 線程ID
| | | +----------- 進程ID
| | +-------------------------------- 程式計數器對應的指針
| +-------------------------------------------- 信號值(十六進位)
+--------------------------------------------------- 信號名稱
日誌內容 | 實際含義 |
---|---|
SIGSEGV | 信號名稱 |
(0xb) | 信號值(十六進位) |
pc=0x00007f80e0cd095c | 程式計數器對應的指針 |
pid=48 | 進程ID |
tid=140189843019520 | 線程ID |
信號名稱是操作系統自身的一種信息,CentOS 7下共有以下35種,可在/usr/include/bits/signum.h中查看其具體的聲明
信號名稱 | 信號值 | 含義 |
---|---|---|
SIGHUP | 1 | Hangup (POSIX). |
SIGINT | 2 | Interrupt (ANSI). |
SIGQUIT | 3 | Quit (POSIX). |
SIGILL | 4 | Illegal instruction (ANSI). |
SIGTRAP | 5 | Trace trap (POSIX). |
SIGABRT | 6 | Abort (ANSI). |
SIGIOT | 6 | IOT trap (4.2 BSD). |
SIGBUS | 7 | BUS error (4.2 BSD). |
SIGFPE | 8 | Floating-point exception (ANSI). |
SIGKILL | 9 | Kill, unblockable (POSIX). |
SIGUSR1 | 10 | User-defined signal 1 (POSIX). |
SIGSEGV | 11 | Segmentation violation (ANSI). |
SIGUSR2 | 12 | User-defined signal 2 (POSIX). |
SIGPIPE | 13 | Broken pipe (POSIX). |
SIGALRM | 14 | Alarm clock (POSIX). |
SIGTERM | 15 | Termination (ANSI). |
SIGSTKFLT | 16 | Stack fault. |
SIGCLD | SIGCHLD | Same as SIGCHLD (System V). |
SIGCHLD | 17 | Child status has changed (POSIX). |
SIGCONT | 18 | Continue (POSIX). |
SIGSTOP | 19 | Stop, unblockable (POSIX). |
SIGTSTP | 20 | Keyboard stop (POSIX). |
SIGTTIN | 21 | Background read from tty (POSIX). |
SIGTTOU | 22 | Background write to tty (POSIX). |
SIGURG | 23 | Urgent condition on socket (4.2 BSD). |
SIGXCPU | 24 | CPU limit exceeded (4.2 BSD). |
SIGXFSZ | 25 | File size limit exceeded (4.2 BSD). |
SIGVTALRM | 26 | Virtual alarm clock (4.2 BSD). |
SIGPROF | 27 | Profiling alarm clock (4.2 BSD). |
SIGWINCH | 28 | Window size change (4.3 BSD, Sun). |
SIGPOLL | SIGIO | Pollable event occurred (System V). |
SIGIO | 29 | I/O now possible (4.2 BSD). |
SIGPWR | 30 | Power failure restart (System V). |
SIGSYS | 31 | Bad system call. |
SIGUNUSED | 31 | - |
JVM運行信息
接下來兩行描述了JVM相關版本信息及運行配置信息,內容如下:
# JRE version: Java(TM) SE Runtime Environment (7.0_80-b15) (build 1.7.0_80-b15)
# Java VM: Java HotSpot(TM) 64-Bit Server VM (24.80-b11 mixed mode linux-amd64 compressed oops)
上述文件內容可以得知以下幾點:
- JRE版本號為1.7u80
- JVM版本號為24.80-b11
- JVM運行在Server模式下。對應的是Client模式,Client JVM適合需要快速啟動和較小記憶體空間的應用,它適合交互性的應用,比如GUI;而Server JVM則是看重執行效率的應用的最佳選擇,更適合服務端應用。
- JVM運行在混合模式下,即mixed mode,是JVM預設的運行模式。其他模式還有解釋模式(interpreted mode)和編譯模式(compiled mode),解釋模式會強制JVM以解釋方式執行所有的位元組碼,編譯模式下JVM在第一次使用時會把所有的位元組碼編譯成本地代碼,這兩種模式各有優劣,單獨使用時都會有部分性能上的損失,所以預設使用混合模式即可,混合模式下對於位元組碼中多次被調用的部分,JVM會將其編譯成本地代碼以提高執行效率;而被調用很少(甚至只有一次)的方法在解釋模式下會繼續執行,從而減少編譯和優化成本。
崩潰原因
接下來兩行描述了引發崩潰問題的函數幀
# Problematic frame:
# V [libjvm.so+0x65395c] jni_SetByteArrayRegion+0x19c
| |
| +-- 類似於程式計數器, 以庫名和偏移量表示。
| 對於與位置無關的庫(JVM和其他庫),可以不通過
| 調試器或通過反彙編程式轉存偏移量周圍結
| 構的core文件來定位引起崩潰的指令。
+----------------- 幀類型
幀類型包括以下幾種:
幀類型 | 描述 |
---|---|
C | Native C frame |
j | Interpreted Java frame |
V | VMframe |
v | VMgenerated stub frame |
J | Other frame types, including compiled Java frames |
關於例子中描述的jni_SetByteArrayRegion+0x19c
這部分目前沒有找到相關的資料,官方給的示例中並沒有這一部分,根據字面含義來看,此部分應該表示的是崩潰時正在通過JNI方式調用SetByteArrayRegion方法。
錯誤信息
接下來的錯誤信息部分根據不同錯誤顯示不一樣的內容,在官方給的資料中提供了一份關於內部錯誤的錯誤信息,示例如下:
# An unexpected error has been detected by HotSpot Virtual Machine:
# Internal Error (4F533F4C494E55583F491418160E43505000F5), pid=10226, tid=16384
# Java VM: Java HotSpot(TM) Client VM (1.6.0-rc-b63 mixed mode)
以上示例中提供的內容沒有信號名稱和信號值,只包含了Internal Error
和一個十六進位的字元串,該字元串對出現問題的模塊和行號進行了編碼,通常情況下只對JVM工程師有用。
因為我們生產環境上出現的問題和示例中的問題種類不一樣,所以我們拿到了這樣一段信息:
# Core dump written. Default location: /apps/gateway/project/bin/core or core.48
# If you would like to submit a bug report, please visit:
# http://bugreport.java.com/bugreport/crash.jsp
這段信息中記錄了core dump文件的位置和官方的BUG反饋頁面地址,針對具體問題則需要查看core dump文件了。
線程描述
這一部分描述崩潰時正在運行的線程信息,如果有多個線程同時崩潰,只會列印其中一個線程的信息。
線程信息
Current thread (0x00007f80dc8ce000): JavaThread "RcvThread: com.*.*.*.remote.internal.RemoteTCPConnection[qmid=*,fap=10,peer=/*.*.*.9,localport=*,ssl=no]" daemon [_thread_in_native_trans, id=90,stack(0x00007f807dbb5000,0x00007f807dcb6000)]
第一部分展示了引發致命錯誤的線程,以上為生產的實際信息,因為敏感信息,內容中部分欄位使用*
進行了脫敏。各部分說明如下:
日誌內容 | 實際含義 |
---|---|
(0x0805ac88) | 指針地址 |
JavaThread | 線程類型 |
main | 線程方法名 |
_thread_in_native | 線程狀態 |
id=21139 | 線程ID |
stack(0x7dbb5000, 0x7dcb6000) | 棧區間 |
Current thread (0x0805ac88): JavaThread "main" [_thread_in_native, id=21139, stack(0x7dbb5000, 0x7dcb6000)]
| | | | | |
| | | | | +--------- 棧區間
| | | | +---------------------- ID
| | | +--------------------------------- 狀態
| | +---------------------------------------------- 名稱
| +-------------------------------------------------------- 類型
+---------------------------------------------------------------------- 指針
線程指針指的是JVM內部的線程結構,一般只在實時調試JVM或core文件時才會有用。線程類型包括以下幾種:
JavaThread
VMThread
CompilerThread
GCTaskThread
WatcherThread
ConcurrentMarkSweepThread
部分進程可能包含daemon
標識,表示該進程為守護進程,該項不一定會存在。
接下來的線程狀態中常見的有以下幾種:
Thread State | Description |
---|---|
_thread_uninitialized | 線程未創建,僅在記憶體崩潰時出現。 |
_thread_new | 線程已被創建,但是沒有啟動。 |
_thread_in_native | 線程正在執行本地代碼,可能因為本地代碼的BUG導致此問題。 |
_thread_in_vm | 線程正在執行虛擬機代碼。 |
_thread_in_Java | 線程正在執行編譯或解釋後的Java代碼。 |
_thread_blocked | 線程被阻塞。 |
..._trans | 以上狀態如果後邊帶有_trans ,表示線程正在切換狀態。 |
信號信息
siginfo:si_signo=SIGSEGV: si_errno=0, si_code=0 (SEGV0), si_addr=0x0000000000000000
信號信息描述了導致JVM終止的異常信號信息,此部分信息根據操作系統不同會有所區別,上邊的例子是linux伺服器下生成的內容,在windows下內容如下:
siginfo: ExceptionCode=0xc0000005, reading address 0xd8ffecf1
| |
| +--------- 線程異常時讀取的地址
+------------------------------------ 異常碼
計數器信息
Registers:
RAX=0x00007f80e2109e00, RBX=0x00007f80dc8ce000, RCX=0x0000000000001a70, RDX=0x00007f80e14c87f0
RSP=0x00007f807dca4710, RBP=0x00007f807dca4780, RSI=0x00007f807dcb47f8, RDI=0x00007f80dc8ce1e8
R8 =0x00007f807dca47a0, R9 =0x000000000000005a, R10=0x0000000000000000, R11=0x0000000000000000
R12=0x00007f807dcb47f8, R13=0x0000000000001a70, R14=0x0000000000000000, R15=0x00007f80e14c8800
RIP=0x00007f80e0cd095c, EFLAGS=0x0000000000010206, CSGSFS=0xffff000000000033, ERR=0x0000000000000007
TRAPNO=0x000000000000000e
此部分內容為程式崩潰時程式計數器中的內容,這一部分的列印格式和伺服器的處理器類型有關,以上為我手中文件的內容,這一部分內容與下一部分結合來看會比較有用(實際上也沒看懂)。
機器指令
Top of Stack: (sp=0x00007f807dca4710)
0x00007f807dca4710: 0000000000007ffe 00007f807dca47a0
0x00007f807dca4720: 00007f807dcb5700 00007f807dcb5680
......
0x00007f807dca48f0: 2020202020202020 2020202020202020
0x00007f807dca4900: 2020202020202020 1c00000020202020
Instructions: (pc=0x00007f80e0cd095c)
0x00007f80e0cd093c: ff 0f 1f 00 48 8b 05 59 b3 7b 00 48 89 da 48 c1
0x00007f80e0cd094c: ea 04 8b 00 21 d0 48 8b 15 cf 6f 7b 00 48 03 02
0x00007f80e0cd095c: c7 00 01 00 00 00 e9 b6 fe ff ff 66 0f 1f 84 00
0x00007f80e0cd096c: 00 00 00 00 45 85 ed 74 40 84 c9 74 77 48 8b 05
以上是博主文件的內容,因為篇幅原因中間部分隱藏了,這一部分內容包含了系統崩潰時程式計數器棧頂的32個指令。這些信息可以通過反編譯程式編譯出崩潰地址附近的指令。需要註意的是A32和AMD64架構的指令長度不一致,所以並不一定能夠反編譯出這部分指令。
記憶體映射信息
Register to memory mapping:
RAX=0x00007f80e2109e00 is an unknown value
RBX=0x00007f80dc8ce000 is a thread
RCX=0x0000000000001a70 is an unknown value
RDX=0x00007f80e14c87f0: <offset 0xe4b7f0> in /usr/java/jdk1.7.0_80/jre/lib/amd64/server/libjvm.so at 0x00007f80e067d000
RSP=0x00007f807dca4710 is pointing into the stack for thread: 0x00007f80dc8ce000
RBP=0x00007f807dca4780 is pointing into the stack for thread: 0x00007f80dc8ce000
RSI=0x00007f807dcb47f8 is pointing into the stack for thread: 0x00007f80dc8ce000
RDI=0x00007f80dc8ce1e8 is an unknown value
R8 =0x00007f807dca47a0 is pointing into the stack for thread: 0x00007f80dc8ce000
R9 =0x000000000000005a is an unknown value
R10=0x0000000000000000 is an unknown value
R11=0x0000000000000000 is an unknown value
R12=0x00007f807dcb47f8 is pointing into the stack for thread: 0x00007f80dc8ce000
R13=0x0000000000001a70 is an unknown value
R14=0x0000000000000000 is an unknown value
R15=0x00007f80e14c8800: <offset 0xe4b800> in /usr/java/jdk1.7.0_80/jre/lib/amd64/server/libjvm.so at 0x00007f80e067d000
此部分信息在博主的文件中存在,但在JDK 7和8兩個版本的文檔中並沒有相關說明。但根據RAX
、RBX
等內容推測是崩潰時CPU各個寄存器中所保存的內容。
線程堆棧
此部分包含線程棧底及棧頂的地址、當前棧指針和未使用的堆棧空間。之後是堆棧幀,最多列印100幀。對於C/C++架構,可能庫名也會被列印。
當出現某些致命錯誤信息時,可能堆棧已經損壞,在這種情況下,這部分信息不可用。
Stack: [0x00007f807dbb5000,0x00007f807dcb6000], sp=0x00007f807dca4710, free space=957k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V [libjvm.so+0x65395c] jni_SetByteArrayRegion+0x19c
Java frames: (J=compiled Java code, j=interpreted, Vv=VM code)
J 1342 java.net.SocketInputStream.socketRead0(Ljava/io/FileDescriptor;[BIII)I (0 bytes) @ 0x00007f80d8bdc0c7 [0x00007f80d8bdc060+0x67]
J 1341 C2 java.net.SocketInputStream.read([BIII)I (567 bytes) @ 0x00007f80d8bfcc90 [0x00007f80d8bfcb00+0x190]
J 1258 C2 com.*.*.*.remote.internal.RemoteTCPConnection.receive([BII)I (775 bytes) @ 0x00007f80d8b87fc0 [0x00007f80d8b87f20+0xa0]
J 1346 C2 com.*.*.*.remote.internal.RemoteRcvThread.receiveBuffer()I (400 bytes) @ 0x00007f80d8c05630 [0x00007f80d8c05580+0xb0]
J 1032 C2 com.*.*.*.remote.internal.RemoteRcvThread.receiveOneTSH()Lcom/*/*/*/remote/internal/system/RfpTSH; (338 bytes) @ 0x00007f80d89dc354 [0x00007f80d89dc120+0x234]
J 1363% C2 com.*.*.*.remote.internal.RemoteRcvThread.run()V (2498 bytes) @ 0x00007f80d8c119b8 [0x00007f80d8c11760+0x258]
j java.lang.Thread.run()V+11
v ~StubRoutines::call_stub
以上日誌內容包含兩個線程堆棧:
- 第一部分堆棧是
Native frames
,列印了本地線程所有的方法調用。然而內聯方法作為上級堆棧的一部分,線程堆棧不會考慮運行時編譯器內聯的Java方法。本地幀的線程堆棧信息提供關於崩潰的重要信息。通過自上而下分析列表中的庫,一般可以確定引起問題的庫並報告給對應的組織。 - 第二部分堆棧是跳過本地幀列印了內聯方法的Java幀,根據崩潰情況可能不會列印本地幀,但大概率會列印Java幀。
其他信息
如果錯誤發生在VM線程或編譯器線程,後邊的例子中會顯示更多信息。例如,問題出現在VM線程中,崩潰時VM線程正在執行的操作將會被列印下來。下麵的例子展示了編譯器線程引起崩潰,執行的內容是編譯器正在編譯方法hs101t004Thread.ackermann
。因為出現的問題不一致,這部分內容並沒有出現在博主的文件中。對於HotSpot虛擬機來說這部分文件可能稍微的有點不同,但都會包含完整的類名和方法名。
Current CompileTask:
HotSpot Client Compiler:754 b
nsk.jvmti.scenarios.hotswap.HS101.hs101t004Thread.ackermann(IJ)J (42 bytes)
進程描述
進程相關內容線上程之後列印,主要包含整個進程的線程列表和記憶體使用情況。
線程列表
Java Threads: ( => current thread )
0x00007f80dc75b000 JavaThread "Thread-12" [_thread_blocked, id=93, stack(0x00007f807d8b2000,0x00007f807d9b3000)]
0x00007f80dc75a000 JavaThread "Thread-11" [_thread_blocked, id=92, stack(0x00007f807d9b3000,0x00007f807dab4000)]
0x00007f80dc759800 JavaThread "Thread-10" [_thread_blocked, id=91, stack(0x00007f807dab4000,0x00007f807dbb5000)]
=>0x00007f80dc8ce000 JavaThread "RcvThread: com.*.*.*.remote.internal.RemoteTCPConnection[qmid=*,fap=10,peer=/*,localport=*,ssl=no]" daemon [_thread_in_native_trans, id=90, stack(0x00007f807dbb5000,0x00007f807dcb6000)]
0x00007f80dc636800 JavaThread "WebSphere MQ Trace Monitor" daemon [_thread_blocked, id=89, stack(0x00007f807dcb6000,0x00007f807ddb7000)]
......
Other Threads:
0x00007f80dc093800 VMThread [stack: 0x00007f807f5f6000,0x00007f807f6f7000] [id=73]
0x00007f80dc0d5000 WatcherThread [stack: 0x00007f807eeef000,0x00007f807eff0000] [id=80]
以上內容為博主手中日誌文件的內容,因為篇幅問題部分內容被省略。此部分線程列表中主要是VM已知的線程,包括Java線程和VM內部的線程。Other Threads
部分主要包含用戶程式創建但沒有包含在VM內部的本地線程。
關於線程的描述與本文之前介紹的線程部分一致。
虛擬機狀態
VM state:synchronizing (normal execution)
接下來的虛擬機狀態主要描述了虛擬機當前的運行狀態,包含以下幾種:
虛擬機狀態 | 描述 |
---|---|
not at a safepoint | 正常執行 |
at safepoint | 虛擬機中所有線程均被阻塞,等待特殊的虛擬機操作完成 |
synchronizing | 一個特殊的虛擬機操作,需要等待虛擬機中所有的線程處於阻塞狀態 |
互斥鎖/管程
VM Mutex/Monitor currently owned by a thread: ([mutex/lock_event])
[0x00007f80dc006060] Safepoint_lock - owner thread: 0x00007f80dc093800
[0x00007f80dc0060e0] Threads_lock - owner thread: 0x00007f80dc093800
[0x00007f80dc0065e0] Heap_lock - owner thread: 0x00007f80dc5a7800
此部分描述了當前線程持有的互斥鎖和管程。如上例所示,這些是虛擬機內部的互斥鎖,不是Java對象關聯的管程。它展示了程式崩潰發生時虛擬機持有鎖的情況,包含了鎖名稱、持有者和虛擬機內部互斥鎖的地址。通常情況下此部分只對非常熟悉HotSpot虛擬機的人有用。持有線程可以線上程列表中找到。
堆概覽
Heap
PSYoungGen total 1397248K, used 1396672K [0x0000000755500000, 0x00000007aaa80000, 0x0000000800000000)
eden space 1396224K, 100% used [0x0000000755500000,0x00000007aa880000,0x00000007aa880000)
from space 1024K, 43% used [0x00000007aa880000,0x00000007aa8f0000,0x00000007aa980000)
to space 1024K, 0% used [0x00000007aa980000,0x00000007aa980000,0x00000007aaa80000)
ParOldGen total 2796544K, used 14720K [0x0000000600000000, 0x00000006aab00000, 0x0000000755500000)
object space 2796544K, 0% used [0x0000000600000000,0x0000000600e60318,0x00000006aab00000)
PSPermGen total 21504K, used 18411K [0x00000005fae00000, 0x00000005fc300000, 0x0000000600000000)
object space 21504K, 85% used [0x00000005fae00000,0x00000005fbffada0,0x00000005fc300000)
此部分內容主要為堆記憶體概覽,輸出內容取決於使用的垃圾回收器,以上內容使用的是JDK 7預設的組合(Parallel Scavenge+Parallel Old)。以上內容中比較奇怪的一點是,我們的項目運行了有一段時間了,結果老年代空間使用率約等於0%,此部分需要排查代碼,另外一點是新生代的使用率達到100%,說明崩潰時可能是在對新生代進行GC。
卡表和本地代碼緩存
Card table byte_map: [0x00007f80d7772000,0x00007f80d879c000] byte_map_base: 0x00007f80d479b000
Code Cache [0x00007f80d879c000, 0x00007f80d8f4c000, 0x00007f80db79c000)
total_blobs=2892 nmethods=2508 adapters=338 free_code_cache=41446Kb largest_free_block=42334144
此部分內容在官方文檔中沒有進行介紹,通過查看其他資料得知,卡表是JVM維護的一種數據結構,用於記錄更改對象時的引用,以便提高GC效率,本地代碼緩存主要用於編譯和保存本地代碼。
此部分具體的用處存疑,希望有瞭解的大佬可以賜教。
編譯事件
Compilation events (10 events):
Event: 83314.233 Thread 0x00007f80dc0c8000 nmethod 2661 0x00007f80d8f2f590 code [0x00007f80d8f2f800, 0x00007f80d8f2fd98]
Event: 83314.235 Thread 0x00007f80dc0c8000 2662 ! bsh.Parser::AndExpression (232 bytes)
Event: 83314.235 Thread 0x00007f80dc0c5000 nmethod 2660 0x00007f80d8f363d0 code [0x00007f80d8f366e0, 0x00007f80d8f36f68]
Event: 83314.246 Thread 0x00007f80dc0c8000 nmethod 2662 0x00007f80d8f2eb50 code [0x00007f80d8f2ed40, 0x00007f80d8f2f0a0]
Event: 83499.918 Thread 0x00007f80dc0c5000 2663 java.math.BigDecimal$StringBuilderHelper::putIntCompact (197 bytes)
Event: 83499.930 Thread 0x00007f80dc0c5000 nmethod 2663 0x00007f80d8f2c750 code [0x00007f80d8f2c8c0, 0x00007f80d8f2cf98]
Event: 84638.783 Thread 0x00007f80dc0c8000 2664 java.util.AbstractList::hashCode (46 bytes)
Event: 84638.841 Thread 0x00007f80dc0c8000 nmethod 2664 0x00007f80d8f39f90 code [0x00007f80d8f3a100, 0x00007f80d8f3a378]
Event: 85085.178 Thread 0x00007f80dc0c5000 2665 sun.nio.ch.EPollSelectorImpl::updateSelectedKeys (150 bytes)
Event: 85085.233 Thread 0x00007f80dc0c5000 nmethod 2665 0x00007f80d8f38590 code [0x00007f80d8f387c0, 0x00007f80d8f39248]
此部分內容在官方文檔中未進行介紹,不過根據內容來看,此部分包含了程式崩潰前執行的十次編譯任務。
GC事件
GC Heap History (10 events):
Event: 84610.584 GC heap before
{Heap before GC invocations=309 (full 0):
PSYoungGen total 1397248K, used 1396764K [0x0000000755500000, 0x00000007aaa80000, 0x0000000800000000)
eden space 1396224K, 100% used [0x0000000755500000,0x00000007aa880000,0x00000007aa880000)
from space 1024K, 52% used [0x00000007aa980000,0x00000007aaa071b8,0x00000007aaa80000)
to space 1024K, 0% used [0x00000007aa880000,0x00000007aa880000,0x00000007aa980000)
ParOldGen total 2796544K, used 14686K [0x0000000600000000, 0x00000006aab00000, 0x0000000755500000)
object space 2796544K, 0% used [0x0000000600000000,0x0000000600e57bd8,0x00000006aab00000)
PSPermGen total 21504K, used 18408K [0x00000005fae00000, 0x00000005fc300000, 0x0000000600000000)
object space 21504K, 85% used [0x00000005fae00000,0x00000005fbffa340,0x00000005fc300000)
Event: 84610.588 GC heap after
Heap after GC invocations=309 (full 0):
PSYoungGen total 1397248K, used 320K [0x0000000755500000, 0x00000007aaa80000, 0x0000000800000000)
eden space 1396224K, 0% used [0x0000000755500000,0x0000000755500000,0x00000007aa880000)
from space 1024K, 31% used [0x00000007aa880000,0x00000007aa8d0000,0x00000007aa980000)
to space 1024K, 0% used [0x00000007aa980000,0x00000007aa980000,0x00000007aaa80000)
ParOldGen total 2796544K, used 14686K [0x0000000600000000, 0x00000006aab00000, 0x0000000755500000)
object space 2796544K, 0% used [0x0000000600000000,0x0000000600e57bd8,0x00000006aab00000)
PSPermGen total 21504K, used 18408K [0x00000005fae00000, 0x00000005fc300000, 0x0000000600000000)
object space 21504K, 85% used [0x00000005fae00000,0x00000005fbffa340,0x00000005fc300000)
}
......
此部分內容同樣在官方文檔中沒有說明,但是瞭解JVM垃圾回收的應該都可以看懂,因為篇幅問題只展示前兩段。以下對內容進行簡要說明:
Event: 84610.584 GC heap before
|
+------垃圾回收發生的時間,單位秒,從JVM啟動開始計時
Heap before GC invocations=309 (full 0):
| |
| +------此前Full GC發生的次數
+---------------當前GC次數(此處代表第309次GC)
其他部分表示JVM記憶體各個分區在GC前後的使用情況,如果出現GC後相較於GC前記憶體使用量未下降的情況,則表示可能出現記憶體溢出。
逆向優化事件
Deoptimization events (10 events):
Event: 62518.966 Thread 0x00007f80dc5a7800 Uncommon trap: reason=unstable_if action=reinterpret pc=0x00007f80d8f1cea4 method=bsh.NameSpace.getClass(Ljava/lang/String;)Ljava/lang/Class; @ 16
Event: 65561.299 Thread 0x00007f801400c000 Uncommon trap: reason=unstable_if action=reinterpret pc=0x00007f80d8d46158 method=sun.nio.ch.Util$BufferCache.get(I)Ljava/nio/ByteBuffer; @ 26
Event: 67079.495 Thread 0x00007f801400c000 Uncommon trap: reason=unstable_if action=reinterpret pc=0x00007f80d8cad61c method=sun.nio.ch.Util$BufferCache.get(I)Ljava/nio/ByteBuffer; @ 26
Event: 67175.303 Thread 0x00007f80dc8ce000 Uncommon trap: reason=unstable_if action=reinterpret pc=0x00007f80d8e80c44 method=com.*.*.*.remote.internal.system.RemoteProxyQueue.addMessage(Lcom/*/*/*/remote/internal/system/RemoteTls;Lcom/*/*/*/remote/internal/system/RfpTSH;Lcom/*/
Event: 67175.364 Thread 0x00007f801400c000 Uncommon trap: reason=unstable_if action=reinterpret pc=0x00007f80d8c7c650 method=sun.nio.ch.Util$BufferCache.get(I)Ljava/nio/ByteBuffer; @ 26
Event: 70454.736 Thread 0x00007f80dc5b7000 Uncommon trap: reason=unstable_if action=reinterpret pc=0x00007f80d8b23004 method=java.lang.Long.getChars(JI[C)V @ 24
Event: 70650.379 Thread 0x00007f80dc5ad000 Uncommon trap: reason=unstable_if action=reinterpret pc=0x00007f80d8e0f700 method=java.util.ArrayDeque.pollFirst()Ljava/lang/Object; @ 13
Event: 76653.752 Thread 0x00007f80dc09a000 Uncommon trap: reason=bimorphic action=maybe_recompile pc=0x00007f80d8d837b4 method=java.lang.System$2.invokeFinalize(Ljava/lang/Object;)V @ 1
Event: 84618.642 Thread 0x00007f801400c000 Uncommon trap: reason=unstable_if action=reinterpret pc=0x00007f80d8eef598 method=sun.nio.ch.SocketChannelImpl.translateReadyOps(IILsun/nio/ch/SelectionKeyImpl;)Z @ 140
Event: 84618.654 Thread 0x00007f801400c000 Uncommon trap: reason=unstable_if action=reinterpret pc=0x00007f80d8b00478 method=sun.nio.ch.EPollSelectorImpl.updateSelectedKeys()I @ 124
JVM會在運行過程中對代碼進行編譯優化,過程中包含一部分不穩定的激進優化,當激進優化不成立時會通過逆向優化退回到解釋狀態進行執行,此部分就是介紹的崩潰前的十次逆向優化內容,這部分內容在官方文檔中並沒有詳細說明。
內部錯誤
Internal exceptions (10 events):
Event: 85322.248 Thread 0x00007f80dc5ad000 Threw 0x00000007a5d71078 at /HUDSON/workspace/7u-2-build-linux-amd64/jdk7u80/2329/hotspot/src/share/vm/prims/jvm.cpp:1319
Event: 85322.249 Thread 0x00007f80dc5ad000 Threw 0x00000007a5d986f8 at /HUDSON/workspace/7u-2-build-linux-amd64/jdk7u80/2329/hotspot/src/share/vm/prims/jvm.cpp:1319
Event: 85322.249 Thread 0x00007f80dc5ad000 Threw 0x00000007a5d98a20 at /HUDSON/workspace/7u-2-build-linux-amd64/jdk7u80/2329/hotspot/src/share/vm/prims/jvm.cpp:1319
Event: 85322.249 Thread 0x00007f80dc5ad000 Threw 0x00000007a5d9b088 at /HUDSON/workspace/7u-2-build-linux-amd64/jdk7u80/2329/hotspot/src/share/vm/prims/jvm.cpp:1319
Event: 85322.738 Thread 0x00007f80dc5a8800 Threw 0x00000007a92c18f8 at /HUDSON/workspace/7u-2-build-linux-amd64/jdk7u80/2329/hotspot/src/share/vm/prims/jvm.cpp:1319
Event: 85322.738 Thread 0x00007f80dc5a8800 Threw 0x00000007a92c1c20 at /HUDSON/workspace/7u-2-build-linux-amd64/jdk7u80/2329/hotspot/src/share/vm/prims/jvm.cpp:1319
Event: 85322.738 Thread 0x00007f80dc5a8800 Threw 0x00000007a92c4288 at /HUDSON/workspace/7u-2-build-linux-amd64/jdk7u80/2329/hotspot/src/share/vm/prims/jvm.cpp:1319
Event: 85322.741 Thread 0x00007f80dc5b7000 Threw 0x00000007a982b580 at /HUDSON/workspace/7u-2-build-linux-amd64/jdk7u80/2329/hotspot/src/share/vm/prims/jvm.cpp:1319
Event: 85322.741 Thread 0x00007f80dc5b7000 Threw 0x00000007a982b8a8 at /HUDSON/workspace/7u-2-build-linux-amd64/jdk7u80/2329/hotspot/src/share/vm/prims/jvm.cpp:1319
Event: 85322.742 Thread 0x00007f80dc5b7000 Threw 0x00000007a982df10 at /HUDSON/workspace/7u-2-build-linux-amd64/jdk7u80/2329/hotspot/src/share/vm/prims/jvm.cpp:1319
此部分在官方文檔中並沒有進行說明,且當前文件中的內容可閱讀的信息較少,在查閱相關資料過程中發現部分錯誤此處可能列印具體的異常信息。當前文件中可以看出在0.5s內發生了10次內部錯誤,綜合文件其他地方的時間來看,這個時間點很接近崩潰發生的時間,且與最後一次未發生的GC時間基本相符。
事件
Events (10 events):
Event: 85322.248 loading class 0x00007f80dc52a460 done
Event: 85322.248 loading class 0x00007f80dc52a460
Event: 85322.248 loading class 0x00007f80dc52a460 done
Event: 85322.249 loading class 0x00007f80dc52a460
Event: 85322.249 loading class 0x00007f80dc52a460 done
Event: 85322.738 loading class 0x00007f80dc52a460
Event: 85322.738 loading class 0x00007f80dc52a460 done
Event: 85322.741 loading class 0x00007f80dc52a460
Event: 85322.741 loading class 0x00007f80dc52a460 done
Event: 85322.742 Executing VM operation: ParallelGCFailedAllocation
此部分在官方文檔中並沒有進行說明,此部分主要包含JVM在崩潰前的十次操作事件,以上內容可以看出最後一次事件為ParallelGCFailedAllocation,在網上沒有查到這個操作的資料,根據字面含義為執行Parallel垃圾回收器回收失敗後的再分配過程,此處的疑點是在崩潰前新生代記憶體使用率已經是100%了,可能是這個事件導致的記憶體溢出。
記憶體信息
Dynamic libraries:
00400000-00401000 r-xp 00000000 fd:01 268667146 /usr/java/jdk1.7.0_80/bin/java
00600000-00601000 rw-p 00000000 fd:01 268667146 /usr/java/jdk1.7.0_80/bin/java
01097000-010b8000 rw-p 00000000 00:00 0 [heap]
......
7f80e210c000-7f80e210d000 r--p 0001f000 fd:01 302335055 /usr/lib64/ld-2.17.so
7f80e210d000-7f80e210e000 rw-p 00020000 fd:01 302335055 /usr/lib64/ld-2.17.so
7f80e210e000-7f80e210f000 rw-p 00000000 00:00 0
7fff254c6000-7fff254e7000 rw-p 00000000 00:00 0 [stack]
7fff25514000-7fff25516000 r-xp 00000000 00:00 0 [vdso]
ffffffffff600000-ffffffffff601000 r-xp 00000000 00:00 0 [vsyscall]
此部分信息展示了崩潰時的記憶體信息,這個列表在比較大的應用程式中可能會比較長,博主的文件中這一部分不算空行占了350多行。此部分在調試崩潰情況時非常有用,可以描述被使用的庫及其使用的記憶體地址,以及堆、棧和保護單元的地址。
此部分內容的格式與操作系統相關,以上例子為Linux下的格式,以下是對內容的簡單介紹:
日誌內容 | 實際含義 |
---|---|
00400000-00401000 | 記憶體區域 |
r-xp | 許可權(r:讀取、w:寫入、x:執行、p:私有、s:共用) |
00000000 | 文件偏移量 |
fd:01 | 文件所在設備的主要和次要ID |
268667146 | 索引編號 |
/usr/java/jdk1.7.0_80/bin/java | 文件名 |
00400000-00401000 r-xp 00000000 fd:01 268667146 /usr/java/jdk1.7.0_80/bin/java
|<------------->| ^ ^ ^ ^ |<- -------------------------->|
| | | | | |
| | | | | +------------------- 文件名
| | | | +------------------------------------------- 索引編號
| | | +------------------------------------------------- 文件所在設備的主要和次要ID
| | +--------------------------------------------------------- 文件偏移量
| +---------------------------------------------------------------- 許可權(r:讀取、w:寫入、x:執行、p:私有、s:共用)
+--------------------------------------------------------------------------- 記憶體區域
虛擬機參數和環境變數
VM Arguments:
jvm_args: -Dfile.encoding=UTF8 -Dsun.jnu.encoding=UTF8 -Xms4096m -Xmx8192m
java_command: com.giantstone.commgateway.startup.Bootstrap ../../gateway-comm-lib/lib ../config ../deploy front_core start
Launcher Type: SUN_STANDARD
Environment Variables:
PATH=/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin:/root/bin
SHELL=/bin/bash
此部分應該是最簡單易懂的,描述的是和Java虛擬機有關的環境變數及其自身運行時使用的參數。
信號處理器
Signal Handlers:
SIGSEGV: [libjvm.so+0x9a3b20], sa_mask[0]=0x7ffbfeff, sa_flags=0x10000004
SIGBUS: [libjvm.so+0x9a3b20], sa_mask[0]=0x7ffbfeff, sa_flags=0x10000004
SIGFPE: [libjvm.so+0x81e740], sa_mask[0]=0x7ffbfeff, sa_flags=0x10000004
SIGXFSZ: [libjvm.so+0x81e740], sa_mask[0]=0x7ffbfeff, sa_flags=0x10000004
SIGILL: [libjvm.so+0x81e740], sa_mask[0]=0x7ffbfeff, sa_flags=0x10000004
SIGUSR1: SIG_DFL, sa_mask[0]=0x00000000, sa_flags=0x00000000
SIGUSR2: [libjvm.so+0x81ffb0], sa_mask[0]=0x00000000, sa_flags=0x10000004
SIGHUP: SIG_IGN, sa_mask[0]=0x00000000, sa_flags=0x00000000
SIGINT: SIG_IGN, sa_mask[0]=0x00000000, sa_flags=0x00000000
SIGTERM: [libjvm.so+0x8210d0], sa_mask[0]=0x7ffbfeff, sa_flags=0x10000004
SIGQUIT: [libjvm.so+0x8210d0], sa_mask[0]=0x7ffbfeff, sa_flags=0x10000004
此部分內容為Linux特有的內容,主要描述針對信號所使用的處理程式。
系統信息
日誌最後一大部分是操作系統相關的內容,也是整個文件當中最直觀的部分,主要包含操作系統版本、CPU信息和記憶體概要。
操作系統
OS:Red Hat Enterprise Linux Server release 7.0 (Maipo)
uname:Linux 3.10.0-514.el7.x86_64 #1 SMP Wed Oct 19 11:24:13 EDT 2016 x86_64
libc:glibc 2.17 NPTL 2.17
rlimit: STACK 8192k, CORE infinity, NPROC infinity, NOFILE 65536, AS infinity
load average:6.02 5.99 5.89
此部分內容為針對操作系統的基本信息和運行中的平均負載情況。
記憶體信息
Memory: 4k page, physical 131862044k(14543760k free), swap 33554428k(33531212k free)
/proc/meminfo:
MemTotal: 131862044 kB
MemFree: 14543760 kB
MemAvailable: 120724836 kB
Buffers: 1584 kB
Cached: 107254088 kB
......
HugePages_Surp: 0
Hugepagesize: 2048 kB
DirectMap4k: 378736 kB
DirectMap2M: 133838848 kB
記憶體部分在文件中實際分了兩部分,這裡我們放在一起展示,因為篇幅原因記憶體詳情只展示開頭和結尾的部分,這部分主要包含系統運行時的記憶體使用情況,這裡有個問題,我們的應用跑在容器之中,分配的容器記憶體只有8G,但這裡獲取到的記憶體則是整台宿主機的記憶體。
CPU信息
CPU:total 32 (1 cores per cpu, 1 threads per core) family 6 model 6 stepping 3, cmov, cx8, fxsr, mmx, sse, sse2, sse3, tsc
/proc/cpuinfo:
# 此處省略掉每個CPU核心的描述信息
CPU信息部分包括概覽以及對每個核心的描述,因為篇幅原因省略掉了,此處和記憶體存在同樣的問題,容器內的應用獲取到了宿主機的CPU信息。
總結
通過查詢相關資料,對JVM致命錯誤日誌內容有了初步的瞭解,在學習的過程中發現了以下幾個疑點:
- 崩潰時正在通過JNI方式調用SetByteArrayRegion這個方法進行數組處理,通過堆棧信息可以看到是在調用RemoteTCPConnection.receive()時報的錯,而這個類是我們引用的MQ中的方法,後續需要對相關的代碼進行排查,確定使用的版本是否正常,相關代碼是否存在問題。
- 在查看堆記憶體和事件部分可以得知,在崩潰時記憶體中新生代的使用率已經達到了100%,在事件中也觸發了ParallelGCFailedAllocation,考慮是不是因為在調用RemoteTCPConnection.receive()時出現了記憶體溢出問題。
- 容器內的應用在獲取硬體信息時獲取到了宿主機的硬體信息,這個地方會有一個隱患,java預設使用物理記憶體的一半來作為虛擬機的記憶體,如果說在使用java時沒有手動設定
Xmx
參數,也就意味著該進程使用的記憶體可能會遠大於容器的記憶體。此份日誌文件中可以看到設置的-Xmx=8192m
,但實際我們給容器分配的記憶體也是8G,而另外的應用中使用的Tomcat並沒有設置此參數。 - 在排查問題時還發現JDK 7本身與容器存在相容性問題,網上的資料建議使用JDK 8u131以後的版本,但是博主未在JDK 8u131的更新日誌中發現相關內容,倒是在8u191的更新日誌中找到了,目前計劃將JDK更新至8u201,同時使用G1垃圾回收器,驗證能不能解決之前出現的GC問題。
以上是排查過程中發現的問題,本人水平有限,可能問題定位不准確,這份總結僅供各位參考,實際的問題還需要多方面的排查和驗證。