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

jopen 9年前發布 | 31K 次閱讀 JVM Java開發

當jvm出現致命錯誤時,會生成一個錯誤文件 hs_err_pid<pid>.log,其中包括了導致jvm crash的重要信息,可以通過分析該文件定位到導致crash的根源,從而改善以保證系統穩定。當出現crash時,該文件默認會生成到工作目錄下,然而可以通過jvm參數指定生成路徑(JDK6中引入):

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

該文件包含如下幾類關鍵信息:

  • 日志頭文件

    </li>

  • 導致crash的線程信息

    </li>

  • 所有線程信息

    </li>

  • 安全點和鎖信息

    </li>

  • 堆信息

    </li>

  • 本地代碼緩存

    </li>

  • 編譯事件

    </li>

  • gc相關記錄

    </li>

  • jvm內存映射

    </li>

  • jvm啟動參數

    </li>

  • 服務器信息

    </li> </ul>

    下面用一個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

    </pre>

    這里一個重要信息是“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

      </li>

    • j: Interpreted Java frame

      </li>

    • V: VMframe

      </li>

    • v: VMgenerated stub frame

      </li>

    • J: Other frame types, including compiled Java frames

      </li> </ul>

      加上前面對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</pre>

      以上表示導致出錯的線程是0x00007fb7b4014800(指針),線程類型是JavaThread,JavaThread表示執行的是java線程,關于該線程其它類型還可能是:

      • VMThread:jvm的內部線程

        </li>

      • CompilerThread:用來調用JITing,實時編譯裝卸class 。 通常,jvm會啟動多個線程來處理這部分工作,線程名稱后面的數字也會累加,例如:CompilerThread1

        </li>

      • GCTaskThread:執行gc的線程

        </li>

      • WatcherThread:jvm周期性任務調度的線程,是一個單例對象。 該線程在JVM內使用得比較頻繁,比如:定期的內存監控、JVM運行狀況監控,還有我們經常需要去執行一些jstat 這類命令查看gc的情況

        </li>

      • ConcurrentMarkSweepThread:jvm在進行CMS GC的時候,會創建一個該線程去進行GC,該線程被創建的同時會創建一個SurrogateLockerThread(簡稱SLT)線程并且啟動它,SLT啟動之后,處于等待階段。CMST開始GC時,會發一個消息給SLT讓它去獲取Java層Reference對象的全局鎖:Lock

        </li> </ul>

        后面的"catalina-exec-251"表示線程名,帶有catalina前綴的線程一般是tomcat啟動的線程,“daemon”表示該線程為守護線程,再后面的“[_thread_in_Java”表示線程正在執行解釋或者編譯后的Java代碼,關于該描述其它類型還可能是:

        • _thread_in_native:線程當前狀態

          </li>

        • _thread_uninitialized:線程還沒有創建,它只在內存原因崩潰的時候才出現

          </li>

        • _thread_new:線程已經被創建,但是還沒有啟動

          </li>

        • _thread_in_native:線程正在執行本地代碼,一般這種情況很可能是本地代碼有問題

          </li>

        • _thread_in_vm:線程正在執行虛擬機代碼

          </li>

        • _thread_in_Java:線程正在執行解釋或者編譯后的Java代碼

          </li>

        • _thread_blocked:線程處于阻塞狀態

          </li>

        • …_trans:以_trans結尾,線程正處于要切換到其它狀態的中間狀態

          </li> </ul>

          最后的“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</pre>

          安全線信息為正常運行,其它可能得描述還有:

          • not at a safepoint:正常運行狀態

            </li>

          • at safepoint:所有線程都因為虛擬機等待狀態而阻塞,等待一個虛擬機操作完成

            </li>

          • synchronizing:一個特殊的虛擬機操作,要求虛擬機內的其它線程保持等待狀態

            </li> </ul>

            鎖信息為未被線程持有,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:內存區域

              </li>

            • r-xp:權限,r/w/x/p/s分別表示讀/寫/執行/私有/共享

              </li>

            • 00000000:文件內的偏移量

              </li>

            • 08:02:文件位置的majorID和minorID

              </li>

            • 39454583:索引節點號

              </li>

            • /home/service/jdk1.7.0_55/bin/java:文件位置

              </li> </ul>

              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</pre>

              上面是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信息。

              來自:http://my.oschina.net/xionghui/blog/498785

 本文由用戶 jopen 自行上傳分享,僅供網友學習交流。所有權歸原作者,若您的權利被侵害,請聯系管理員。
 轉載本站原創文章,請注明出處,并保留原始鏈接、圖片水印。
 本站是一個以用戶分享為主的開源技術平臺,歡迎各類分享!