Java crash問題分析

Java的應用有時候會由於各類緣由Crash，這時候會產生一個相似java_errorpid.log的錯誤日誌。能夠拿到了

這個日誌，怎樣分析Crash的緣由呢？下面咱們來詳細討論如何分析java_errorpid.log的錯誤日誌。

一. 如何獲得這個日誌文件

若是有一個嚴重的錯誤引發Java進程非正常退出，咱們叫Crash，這時候會產生一個日誌文件。缺省狀況下，這個

文件會產生在工做目錄下。可是，能夠在Java啓動參數經過下面的設置，來改變這個文件的位置和命名規則。例如：

java -XX:ErrorFile=/var/log/java/java_error_%p.log

就將這個錯誤文件放在/var/log/java下，而且以java_error_pid.log的形式出現。

二.產生錯誤的緣由

形成嚴重錯誤的緣由有多種可能性。Java虛擬機自身的Bug是緣由之一，可是這種可能不是很大。在絕大多數狀況下，是因爲系統的庫文件、API或第三方的庫文件形成的；系統資源的短缺也有可能形成這種嚴重的錯誤。在發生了Crash以後，若是沒法定位根本緣由，也應該迅速找到Work Around的方法。

三.對日誌文件的分析

首先要檢查日誌的文件頭：例如，下面是從一個客戶發過來的錯誤日誌的文件頭

－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－
#
# An unexpected error has been detected by HotSpot Virtual Machine:
#
# EXCEPTION_ACCESS_VIOLATION (0xc0000005) at pc=0x0815e87e, pid=7268, tid=4360
#
# Java VM: Java HotSpot(TM) Server VM (1.4.2_13-b06 mixed mode)
# Problematic frame:
# V [jvm.dll+0x15e87e]
#
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

文件頭中有不少有用的信息，「EXCEPTION_ACCESS_VIOLATION 」意味着Java應用Crash的時候，正在運行JVM本身的代碼，而不是外部的Java代碼或其餘類庫代碼。這種狀況極可能是JVM的Bug，可是也不必定。除了「EXCEPTION_ACCESS_VIOLATION 」，還有多是別的信息，例如「SIGSEGV(0xb)」，意味着JVM正在執行本地或JNI的代碼;「EXCEPTION_STACK_OVERFLOW」意味着這是個棧溢出的錯誤。（**********看到這裏咱們知道我報錯時正在運行JVM本身的代碼，而不是外部的Java代碼或其餘類庫代碼*********）

另一個有用的JVM崩潰信息就是：

# Problematic frame:
# V [jvm.dll+0x15e87e]

它說明Crash的時候，JVM正在從哪一個庫文件執行代碼。除了「V」之外，還有多是「C」、「j」、「v」、「J」。具體的表示意思以下：

FrameType Description：
C: Native C frame
j: Interpreted Java frame
V: VMframe
v: VMgenerated stub frame
J: Other frame types, including compiled Java frames

（**********看到這裏咱們知道我報錯時是V: VMframe這種狀況*********）

文件頭以後，是當前線程的DUMP信息，線程以後是JVM進程的DUMP信息，包括全部線程的狀態、地址和ID。最後還有JVM狀態，

Heap狀態，動態鏈接庫等等的信息。這些煩亂的信息中，包含有很是有用的信息。下面咱們根據幾個具體的實例來分析JVM崩潰的典型例子。

四.內存回收引發的Crash

內存回收引發的Crash有如下的特色：在日誌文件頭通常有「 EXCEPTION_ACCESS _VIOLATION」和

「# Problematic frame: # V [jvm.dll+....」的信息，意味着這是在JVM內部處理，並且多半是JVM的Bug。

（**********看到這裏咱們知道我報錯時意味着這是在JVM內部處理，並且多半是JVM的Bug*********）

對於這類問題，最快的方法就是繞過它。

另外，在Thread的DUMP信息最後，還能看到有關內存回收的行爲例如：

--------------- T H R E A D ---------------
Current thread (0x00a56668): VMThread [id=4360]
siginfo: ExceptionCode=0xc0000005, reading address 0x00000057
Registers:
........

Stack: [0x03cf0000,0x03d30000), sp=0x03d2fc18, free space=255k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V [jvm.dll+0x15e87e]

VM_Operation (0x063efbac): full generation collection, mode: safepoint, requested by thread 0x040f83f8
------------------------------------------------------------

能夠清楚的看到JVM正在作 「full generation collection」。另外還有可能看到，其餘的回收行爲：

對於內存回收的錯誤，通常

generation collection for allocation
full generation collection
parallel gc failed allocation
parallel gc failed permanent allocation
parallel gc system gc
（***********這些錯，俺都沒碰到***********）

採起改變回收的算法和參數的方法來繞過去。例如，來自客戶的日誌除了上面的日誌信息，在日誌中Heap信息中還能發現一些其餘信息：

--------------------------------------------------------------
Heap
def new generation total 22592K, used 19530K [0x10010000, 0x11890000, 0x138f0000)
eden space 20096K, 97% used [0x10010000, 0x11322bd8, 0x113b0000)
from space 2496K, 0% used [0x113b0000, 0x113b0000, 0x11620000)
to space 2496K, 0% used [0x11620000, 0x11620000, 0x11890000)
tenured generation total 190696K, used 100019K [0x138f0000, 0x1f32a000, 0x30010000)
the space 190696K, 52% used [0x138f0000, 0x19a9cf38, 0x19a9d000, 0x1f32a000)
compacting perm gen total 38656K, used 38588K [0x30010000, 0x325d0000, 0x34010000)
the space 38656K, 99% used [0x30010000, 0x325bf038, 0x325bf200, 0x325d0000)
----------------------------------------------------------------

上面的信息能看出在Crash的時候，JVM的PermSize空間幾乎已經消耗完了，而且回收算法在壓縮Perm空間的時候出了錯。所以，建議改變內存回收的算法，或擴大PermSize和MaxPermSize的數值。

（*******這個卻是能夠嘗試*******）

五.棧溢出引發的Crash

Java代碼引發的棧溢出，一般不會引發JVM的Crash，而是拋出一個Java異常：java.lang.StackOverflowError。可是在Java虛擬機中，Java的代碼和本地C或C++代碼公用相同的Stack。這樣，在執行本地代碼所形成的棧溢出，就有可能引發JVM的Crash了。棧溢出引發的Crash會在日誌的文件頭中看到「EXCEPTION_STACK_OVERFLOW」字樣。另外，在當前線程的Stack信息中也能發現一些信息。例以下面的例子：

-----------------------------------------------------------------------------------
# An unexpected error has been detected by HotSpot Virtual Machine:
#
# EXCEPTION_STACK_OVERFLOW (0xc00000fd) at pc=0x10001011, pid=296, tid=2940
#
# Java VM: Java HotSpot(TM) Client VM (1.6-internal mixed mode, sharing)
# Problematic frame:
# C [App.dll+0x1011]
#
--------------- T H R E A D ---------------
Current thread (0x000367c0): JavaThread "main" [_thread_in_native, id=2940]
:
Stack: [0x00040000,0x00080000), sp=0x00041000, free space=4k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
C [App.dll+0x1011]
C [App.dll+0x1020]
C [App.dll+0x1020]
:
C [App.dll+0x1020]
C [App.dll+0x1020]
......
Java frames: (J=compiled Java code, j=interpreted, Vv=VM code)
j Test.foo()V+0
j Test.main([Ljava/lang/String;)V+0
v ~StubRoutines::call_stub

--------------------------------------------------------------------------------

在上面的信息中，能夠發現這是個棧溢出的錯誤。而且當前棧剩餘的空間已經很小了(free space =4k)。

所以建議將JVM的Stack的尺寸調大，主要設計兩個參數：「-Xss」 和「-XX:StackShadowPages=n」。可是，將棧的尺寸調大，也意味着在有限的內存資源中，能打開的最大線程數會減小。

 

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

 

致命錯誤出現的時候，JVM生成了hs_err_pid<pid>.log這樣的文件，其中每每包含了虛擬機崩潰緣由的重要信息。由於常常遇到，在這篇文章裏，我挑選了一個，而且逐段分析它包含的內容（文件能夠在文章最後下載）。默認狀況下文件是建立在工做目錄下的（若是沒權限建立的話JVM會嘗試把文件寫到/tmp這樣的臨時目錄下面去），固然，文件格式和路徑也能夠經過參數指定，好比：

java -XX:ErrorFile=/var/log/java/java_error%p.log

這個文件將包括：

• 觸發致命錯誤的操做異常或者信號；
• 版本和配置信息；
• 觸發致命異常的線程詳細信息和線程棧；
• 當前運行的線程列表和它們的狀態；
• 堆的總括信息；
• 加載的本地庫；
• 命令行參數；
• 環境變量；
• 操做系統CPU的詳細信息。

首先，看到的是對問題的概要介紹：

#  SIGSEGV (0xb) at pc=0x03568cf4, pid=16819, tid=3073346448

一個非預期的錯誤被JRE檢測到，其中：

• SIGSEGV是信號名稱
• 0xb是信號碼
• pc=0x03568cf4指的是程序計數器的值
• pid=16819是進程號
• tid=3073346448是線程號

若是你對JVM有了解，應該不會對這些東西陌生。

接下來是JRE和JVM的版本信息：

# JRE version: 6.0_32-b05
# Java VM: Java HotSpot(TM) Server VM (20.7-b02 mixed mode linux-x86 )

運行在mixed模式下。

而後是問題幀的信息：

# Problematic frame:
# C  [libgtk-x11-2.0.so.0+0x19fcf4]  __float128+0x19fcf4

C：幀類型爲本地幀，幀的類型包括：

• C：本地C幀
• j：解釋的Java幀
• V：虛擬機幀
• v：虛擬機生成的存根棧幀
• J：其餘幀類型，包括編譯後的Java幀
• libgtk-x11-2.0.so.0+0x19fcf4：和程序計數器（pc）表達的含義同樣，可是用的是本地so庫+偏移量的方式。

接下去第一部分是線程信息：

Current thread (0x09f30c00):  JavaThread」main」[_thread_in_native, id=16822, stack(0xb72a8000,0xb72f9000)]

當前線程的：

• 0x09f30c00：指針
• JavaThread：線程類型，可能的類型包括：
  • JavaThread
  • VMThread
  • CompilerThread
  • GCTaskThread
  • WatcherThread
  • ConcurrentMarkSweepThread
• main：名字
  • _thread_in_native：線程當前狀態，狀態枚舉包括：
  • _thread_uninitialized：線程尚未建立，它只在內存緣由崩潰的時候纔出現
  • _thread_new：線程已經被建立，可是尚未啓動
  • _thread_in_native：線程正在執行本地代碼，通常這種狀況極可能是本地代碼有問題
  • _thread_in_vm：線程正在執行虛擬機代碼
  • _thread_in_Java：線程正在執行解釋或者編譯後的Java代碼
  • _thread_blocked：線程處於阻塞狀態
  • …_trans：以_trans結尾，線程正處於要切換到其它狀態的中間狀態
• id=16822：線程ID
• 0xb72a8000,0xb72f9000：棧區間

siginfo:si_signo=SIGSEGV: si_errno=0, si_code=1(SEGV_MAPERR), si_addr=0×00000010

這部分是致使虛擬機終止的非預期的信號信息，含義前面已經大體提到過了。其中si_errno和si_code是Linux下用來鑑別異常的，Windows下是一個ExceptionCode。

EAX=0×00000000,EBX=0x0375dd84,ECX=0×00000000,EDX=0×00000000
ESP=0xb72f0fa0,EBP=0xb72f0fb8,ESI=0×00000000,EDI=0x0a6c1800
EIP=0x03568cf4,EFLAGS=0×00010246,CR2=0×00000010

這是寄存器上下文。

Top of Stack: (sp=0xb72f0fa0)
0xb72f0fa0:  00000000004022500040217f 0375dd84
0xb72f0fb0:  000000000a6c1800 b72f0fe8 0356c2c0
0xb72f0fc0:  000000000a6c1800 b72f0fe8 003b3e77
0xb72f0fd0:   003e6c8b 0a1a70d0 0a193358 0375dd84
0xb72f0fe0:   0a276418 0a276418 b72f1048 03536c56
0xb72f0ff0:   0acad000 0b3ca978 0000000c 00dd0674
0xb72f1000:  000000030a2c7d50 b72f1038 0000330c
0xb72f1010:   ffffffff ffffffff0000000100000001
Instructions: (pc=0x03568cf4)
0x03568cd4:  8914248975f889d6897d fc89c7 e8 7e 1b
0x03568ce4:   ea ff8934248987d4020000e83000ea ff
0x03568cf4:   8b4010893c24c7442408000000008987
0x03568d04:   d00200008b838824000089442404e8 dd

棧頂程序計數器旁的操做碼，它們能夠被反彙編成系統崩潰前執行的指令。

Register to memory mapping:
EAX=0x00000000isan unknown value
EBX=0x0375dd84: <offset 0x394d84>in/usr/lib/libgtk-x11-2.0.so.0 at 0x033c9000
ECX=0x00000000isan unknown value
EDX=0x00000000isan unknown value
ESP=0xb72f0fa0ispointing into the stackforthread: 0x09f30c00
EBP=0xb72f0fb8ispointing into the stackforthread: 0x09f30c00
ESI=0x00000000isan unknown value
EDI=0x0a6c1800isan unknown value

寄存器和內存映射信息。

Stack: [0xb72a8000,0xb72f9000],  sp=0xb72f0fa0,  free space=291k
Native frames: (J=compiled Java code, j=interpreted, Vv=VMcode,C=native code)
C [libgtk-x11-2.0.so.0+0x19fcf4]  __float128+0x19fcf4
C [libgtk-x11-2.0.so.0+0x1a32c0]  __float128+0xc0
… …
C [libswt-pi-gtk-3738.so+0x33f6a]  Java_org_eclipse_swt_internal_gtk_OS__1Call+0xf
J org.eclipse.swt.internal.gtk.OS._Call(III)I
J org.eclipse.swt.internal.gtk.OS.Call(III)I
Java frames: (J=compiled Java code, j=interpreted, Vv=VMcode)
J org.eclipse.swt.internal.gtk.OS._Call(III)I
J org.eclipse.swt.internal.gtk.OS.Call(III)I
j  org.eclipse.swt.widgets.Widget.fixedSizeAllocateProc(II)I+5
j  org.eclipse.swt.widgets.Display.fixedSizeAllocateProc(II)I+17
v  ~StubRoutines::call_stub
… …

線程棧。包含了地址、棧頂、棧計數器和線程還沒有使用的棧信息，因爲棧可能很是長，打印的長度有限制，可是至少本地棧和Java棧都打印出來了（不少時候本地棧打印不出來，可是Java棧通常都能打印出來）。從中能夠看到，Eclipse的虛擬機崩潰了。

Java Threads: ( => current thread )
  0x0b4c1000 JavaThread」Worker-247″[_thread_blocked, id=25417, stack(0x741bc000,0x7420d000)]
  0x0a300c00 JavaThread」Worker-246″[_thread_blocked, id=25235, stack(0x7d30c000,0x7d35d000)]
… …

線程信息。一目瞭然，不解釋了。

VMstate:notat safepoint (normal execution)

虛擬機狀態。包括：

• not at a safepoint：正常運行狀態；
• at safepoint：全部線程都由於虛擬機等待狀態而阻塞，等待一個虛擬機操做完成；
• synchronizing：一個特殊的虛擬機操做，要求虛擬機內的其它線程保持等待狀態。

VMMutex/Monitor currently owned by a thread: None

虛擬機的Mutex和Monitor目前沒有被線程持有。Mutex是虛擬機內部的鎖，而Monitor則關聯到了Java對象。

Heap
PSYoungGen      total149056K, used125317K[0xa9700000, 0xb41a0000, 0xb41a0000)
eden space123520K,95% used [0xa9700000,0xb0ac0de0,0xb0fa0000)
from space25536K,26% used [0xb28b0000,0xb2f50748,0xb41a0000)
to   space25600K,0% used [0xb0fa0000,0xb0fa0000,0xb28a0000)
PSOldGen        total261248K, used239964K[0x941a0000, 0xa40c0000, 0xa9700000)
object space261248K,91% used [0x941a0000,0xa2bf7018,0xa40c0000)
PSPermGen       total163328K, used130819K[0x841a0000, 0x8e120000, 0x941a0000)
object space163328K,80% used [0x841a0000,0x8c160c40,0x8e120000)

堆信息。新生代、老生代、永久代。對JVM有了解的人應該都清楚，不解釋了。

Code Cache  [0xb4262000, 0xb5ac2000, 0xb7262000)
 total_blobs=5795nmethods=5534adapters=209free_code_cache=25103616largest_free_block=38336

代碼緩存（Code Cache）。這是一塊用於編譯和保存本地代碼的內存，注意是本地代碼，它和PermGen（永久代）是不同的，永久帶是用來存放Java類定義的。

Dynamic libraries:
00101000-00122000 r-xp 00000000 08:01 3483560    /usr/lib/libjpeg.so.62.0.0
00122000-00123000 rwxp 00020000 08:01 3483560    /usr/lib/libjpeg.so.62.0.0
00125000-00130000 r-xp 00000000 08:01 9093202    /lib/libgcc_s-4.1.2-20080825.so.1
00130000-00131000 rwxp 0000a000 08:01 9093202    /lib/libgcc_s-4.1.2-20080825.so.1
... ...

內存映射。這些信息是虛擬機崩潰時的虛擬內存列表區域。在定位崩潰緣由的時候，它能夠告訴你哪些類庫正在被使用，位置在哪裏，還有堆棧和守護頁信息。就以列表中第一條爲例說明：

• 00101000-00122000：內存區域
• r-xp：權限，r/w/x/p/s分別表示讀/寫/執行/私有/共享
• 00000000：文件內的偏移量
• 08:01：文件位置的majorID和minorID
• 3483560：索引節點號
• /usr/lib/libjpeg.so.62.0.0：文件位置

每個lib都有兩塊虛擬內存區域——代碼和數據，它們的權限不一樣，代碼區域是r-xp；數據區域是rwxp。守護頁（guard page）由權限爲--xp和rwxp的一對組成。

VMArguments:
jvm_args: -Dosgi.requiredJavaVersion=1.5-XX:MaxPermSize=256m -Xms40m -Xmx512m -Dorg.eclipse.swt.browser.XULRunnerPath=''
java_command: /.../eclipse/plugins/org.eclipse.equinox.launcher_1.2.0.v20110502.jar -os linux -ws gtk -arch x86 -showsplash -launcher /.../eclipse/eclipse -name Eclipse ...
Launcher Type:SUN_STANDARD
Environment Variables:
PATH=...
DISPLAY=:0.0

虛擬機參數和環境變量。

Signal Handlers:
SIGSEGV: [libjvm.so+0x726440], sa_mask[0]=0x7ffbfeff, sa_flags=0×10000004
SIGBUS: [libjvm.so+0x726440], sa_mask[0]=0x7ffbfeff, sa_flags=0×10000004
… …

信號句柄。對於Linux下的信號機制，參閱wiki百科。

OS:Red Hat Enterprise Linux Client release 5.4 (Tikanga)
uname:Linux 2.6.18-164.el5 #1 SMP Tue Aug 18 15:51:54 EDT 2009 i686
libc:glibc 2.5 NPTL 2.5
rlimit: STACK 10240k, CORE 0k, NPROC 65536, NOFILE 1024, AS infinity
load average:1.78 1.58 1.54
/proc/meminfo:
…
CPU:total 4 (4 cores per cpu, 1 threads per core) family 6 model 42 stepping 7, cmov, cx8, fxsr, mmx, sse, sse2, sse3, ssse3
/proc/cpuinfo:
…
Memory: 4k page, physical 3631860k(155144k free), swap 5124724k(5056452k free)

系統信息。

【轉】：http://www.javashuo.com/article/p-awjutjhw-ch.html