JVM致命错误日志(hs_err_pid.log)分析

简介:

当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调用错误等。

现在参考下如下描述:


 
 
  1. # A fatal error has been detected by the Java Runtime Environment: 
  2. #  SIGSEGV (0xb) at pc=0x00007fb8b18fdc6c, pid=191899, tid=140417770411776 
  3. # JRE version: Java(TM) SE Runtime Environment (7.0_55-b13) (build 1.7.0_55-b13) 
  4. # Java VM: Java HotSpot(TM) 64-Bit Server VM (24.55-b03 mixed mode linux-amd64 compressed oops) 
  5. # Problematic frame: 
  6. # J  org.apache.http.impl.cookie.BestMatchSpec.formatCookies(Ljava/util/List;)Ljava/util/List; 
  7. # Failed to write core dump. Core dumps have been disabled. To enable core dumping, try "ulimit -c unlimited" before starting Java again 
  8. # If you would like to submit a bug report, please visit: 
  9. #   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,官网描述如下:

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。

所有线程信息

再下面是线程信息:


 
 
  1. Java Threads: ( => current thread ) 
  2.   0x00007fb798015800 JavaThread "catalina-exec-280" daemon [_thread_blocked, id=206093, stack(0x00007fb58d718000,0x00007fb58d819000)] 
  3.   0x00007fb7a4016800 JavaThread ”catalina-exec-279″ daemon [_thread_blocked, id=206091, stack(0x00007fb58d819000,0x00007fb58d91a000)] 
  4.   … …(省略) 
  5.  
  6.   Other Threads: 
  7.   0x00007fb8b4231000 VMThread [stack: 0x00007fb854eb6000,0x00007fb854fb7000] [id=192015
  8.   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对象。

堆信息

再下面是堆信息:


 
 
  1. Heap 
  2.  par new generation   total 2293760K, used 1537284K [0x00000006f00000000x00000007900000000x0000000790000000
  3.   eden space 1966080K,  78% used [0x00000006f00000000x000000074dc97aa80x0000000768000000
  4.   from space 327680K,   0% used [0x00000007680000000x00000007680a95800x000000077c000000
  5.   to   space 327680K,   0% used [0x000000077c0000000x000000077c0000000x0000000790000000
  6.  concurrent mark-sweep generation total 1572864K, used 49449K [0x00000007900000000x00000007f00000000x00000007f0000000
  7.  concurrent-mark-sweep perm gen total 262144K, used 49857K [0x00000007f00000000x00000008000000000x0000000800000000
  8.  
  9.  Card table byte_map: [0x00007fb8b8fa8000,0x00007fb8b9829000] byte_map_base: 0x00007fb8b5828000 

堆信息包括:新生代、老生代、永久代信息。这里标识了使用CMS垃圾收集器。

下面的“Card table”表示一种卡表,是jvm维护的一种数据结构,用于记录更改对象时的引用,以便gc时遍历更少的table和root。

本地代码缓存

再下面是本地代码缓存信息:


 
 
  1. Code Cache  [0x00007fb8b10000000x00007fb8b1a600000x00007fb8b4000000
  2.  total_blobs=3580 nmethods=3111 adapters=421 free_code_cache=38857Kb largest_free_block=39469312 

这是一块用于编译和保存本地代码的内存;注意是本地代码,它和PermGen(永久代)是不一样的,永久代是用来存放jvm和java类的元数据的。

编译事件

再下面是本地代码编译信息:


 
 
  1. Compilation events (10 events): 
  2. Event: 110587.798 Thread 0x00007fb8b425a800 3338             java.util.HashSet::remove (20 bytes) 
  3. Event: 110587.804 Thread 0x00007fb8b425a800 nmethod 3338 0x00007fb8b168a9d0 code [0x00007fb8b168ab600x00007fb8b168afa8
  4. ... ...(省略) 
  5. Event: 112147.387 Thread 0x00007fb8b425a800 3342             org.apache.http.impl.cookie.BestMatchSpec::formatCookies (116 bytes) 
  6. Event: 112147.465 Thread 0x00007fb8b425a800 nmethod 3342 0x00007fb8b18fcd50 code [0x00007fb8b18fd1a00x00007fb8b18ff338

可以看到,一共编译了10次;其中包含org.apache.http.impl.cookie.BestMatchSpec::formatCookies的编译;这和前面的结论相吻合。

gc相关记录

再下面是gc执行记录:


 
 
  1. GC Heap History (10 events): 
  2. Event: 110665.975 GC heap before 
  3. {Heap before GC invocations=255 (full 31): 
  4.  par new generation   total 2293760K, used 1966777K [0x00000006f00000000x00000007900000000x0000000790000000
  5.   eden space 1966080K, 100% used [0x00000006f00000000x00000007680000000x0000000768000000
  6.   from space 327680K,   0% used [0x00000007680000000x00000007680ae4800x000000077c000000
  7.   to   space 327680K,   0% used [0x000000077c0000000x000000077c0000000x0000000790000000
  8.  concurrent mark-sweep generation total 1572864K, used 49237K [0x00000007900000000x00000007f00000000x00000007f0000000
  9.  concurrent-mark-sweep perm gen total 262144K, used 49856K [0x00000007f00000000x00000008000000000x0000000800000000
  10. Event: 110665.981 GC heap after 
  11. Heap after GC invocations=256 (full 31): 
  12.  par new generation   total 2293760K, used 693K [0x00000006f00000000x00000007900000000x0000000790000000
  13.   eden space 1966080K,   0% used [0x00000006f00000000x00000006f00000000x0000000768000000
  14.   from space 327680K,   0% used [0x000000077c0000000x000000077c0ad6f80x0000000790000000
  15.   to   space 327680K,   0% used [0x00000007680000000x00000007680000000x000000077c000000
  16.  concurrent mark-sweep generation total 1572864K, used 49237K [0x00000007900000000x00000007f00000000x00000007f0000000
  17.  concurrent-mark-sweep perm gen total 262144K, used 49856K [0x00000007f00000000x00000008000000000x0000000800000000
  18. ... ...(省略) 

可以看到gc次数为10次(full gc),然后后面描述了每次gc前后的内存信息;看一看到并没有内存不足等问题。

jvm内存映射

再下面是jvm加载的库信息:


 
 
  1. Dynamic libraries: 
  2. 00400000-00401000 r-xp 00000000 08:02 39454583                           /home/service/jdk1.7.0_55/bin/java 
  3. 00600000-00601000 rw-p 00000000 08:02 39454583                           /home/service/jdk1.7.0_55/bin/java 
  4. 013cd000-013ee000 rw-p 00000000 00:00 0                                  [heap] 
  5. 6f0000000-800000000 rw-p 00000000 00:00 0  
  6. 3056400000-3056416000 r-xp 00000000 08:02 57409539                       /lib64/libgcc_s-4.4.7-20120601.so.1 
  7. 3056416000-3056615000 ---p 00016000 08:02 57409539                       /lib64/libgcc_s-4.4.7-20120601.so.1 
  8. 3056615000-3056616000 rw-p 00015000 08:02 57409539                       /lib64/libgcc_s-4.4.7-20120601.so.1 
  9. 353be00000-353be20000 r-xp 00000000 08:02 57409933                       /lib64/ld-2.12.so 
  10. 353c01f000-353c020000 r--p 0001f000 08:02 57409933                       /lib64/ld-2.12.so 
  11. 353c020000-353c021000 rw-p 00020000 08:02 57409933                       /lib64/ld-2.12.so 
  12. ... ...(省略) 

这些信息是虚拟机崩溃时的虚拟内存列表区域。它可以告诉你崩溃原因时哪些类库正在被使用,位置在哪里,还有堆栈和守护页信息。以列表中第一条为例介绍下:

  • 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启动参数信息:


 
 
  1. VM Arguments: 
  2. 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  
  3. java_command: org.apache.catalina.startup.Bootstrap start 
  4. Launcher Type: SUN_STANDARD 
  5.  
  6. Environment Variables: 
  7. JAVA_HOME=/home/service/jdk1.7.0_55 
  8. 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 
  9. SHELL=/bin/bash 

上面是jvm参数,下面是系统的环境配置。

服务器信息

再下面是服务器信息:


 
 
  1. /proc/meminfo: 
  2. MemTotal:       65916492 kB 
  3. MemFree:        14593468 kB 
  4. Buffers:          222452 kB 
  5. Cached:         28502452 kB 
  6. SwapTotal:             0 kB 
  7. SwapFree:              0 kB 
  8. ... ...(省略) 
  9. /proc/cpuinfo: 
  10. processor : 0 
  11. vendor_id : GenuineIntel 
  12. cpu family : 6 
  13. model  : 62 
  14. model name : Intel(R) Xeon(R) CPU E5-2420 v2 @ 2.20GHz 
  15. stepping : 4 
  16. ... ...(省略) 

上面是内存信息,主要关注下swap信息,看看有没有使用虚拟内存;下面是cpu信息。


来源:51CTO

相关实践学习
【涂鸦即艺术】基于云应用开发平台CAP部署AI实时生图绘板
【涂鸦即艺术】基于云应用开发平台CAP部署AI实时生图绘板
相关文章
|
8月前
|
监控 Java Unix
6个Java 工具,轻松分析定位 JVM 问题 !
本文介绍了如何使用 JDK 自带工具查看和分析 JVM 的运行情况。通过编写一段测试代码(启动 10 个死循环线程,分配大量内存),结合常用工具如 `jps`、`jinfo`、`jstat`、`jstack`、`jvisualvm` 和 `jcmd` 等,详细展示了 JVM 参数配置、内存使用、线程状态及 GC 情况的监控方法。同时指出了一些常见问题,例如参数设置错误导致的内存异常,并通过实例说明了如何排查和解决。最后附上了官方文档链接,方便进一步学习。
1159 4
|
7月前
|
监控 容灾 算法
阿里云 SLS 多云日志接入最佳实践:链路、成本与高可用性优化
本文探讨了如何高效、经济且可靠地将海外应用与基础设施日志统一采集至阿里云日志服务(SLS),解决全球化业务扩展中的关键挑战。重点介绍了高性能日志采集Agent(iLogtail/LoongCollector)在海外场景的应用,推荐使用LoongCollector以获得更优的稳定性和网络容错能力。同时分析了多种网络接入方案,包括公网直连、全球加速优化、阿里云内网及专线/CEN/VPN接入等,并提供了成本优化策略和多目标发送配置指导,帮助企业构建稳定、低成本、高可用的全球日志系统。
834 54
|
监控 安全 Apache
什么是Apache日志?为什么Apache日志分析很重要?
Apache是全球广泛使用的Web服务器软件,支持超过30%的活跃网站。它通过接收和处理HTTP请求,与后端服务器通信,返回响应并记录日志,确保网页请求的快速准确处理。Apache日志分为访问日志和错误日志,对提升用户体验、保障安全及优化性能至关重要。EventLog Analyzer等工具可有效管理和分析这些日志,增强Web服务的安全性和可靠性。
369 9
|
10月前
|
存储 SQL 关系型数据库
MySQL日志详解——日志分类、二进制日志bin log、回滚日志undo log、重做日志redo log
MySQL日志详解——日志分类、二进制日志bin log、回滚日志undo log、重做日志redo log、原理、写入过程;binlog与redolog区别、update语句的执行流程、两阶段提交、主从复制、三种日志的使用场景;查询日志、慢查询日志、错误日志等其他几类日志
833 35
MySQL日志详解——日志分类、二进制日志bin log、回滚日志undo log、重做日志redo log
|
10月前
|
存储 缓存 关系型数据库
图解MySQL【日志】——Redo Log
Redo Log(重做日志)是数据库中用于记录数据页修改的物理日志,确保事务的持久性和一致性。其主要作用包括崩溃恢复、提高性能和保证事务一致性。Redo Log 通过先写日志的方式,在内存中缓存修改操作,并在适当时候刷入磁盘,减少随机写入带来的性能损耗。WAL(Write-Ahead Logging)技术的核心思想是先将修改操作记录到日志文件中,再择机写入磁盘,从而实现高效且安全的数据持久化。Redo Log 的持久化过程涉及 Redo Log Buffer 和不同刷盘时机的控制参数(如 `innodb_flush_log_at_trx_commit`),以平衡性能与数据安全性。
488 5
图解MySQL【日志】——Redo Log
|
9月前
|
监控 Java 应用服务中间件
Tomcat log日志解析
理解和解析Tomcat日志文件对于诊断和解决Web应用中的问题至关重要。通过分析 `catalina.out`、`localhost.log`、`localhost_access_log.*.txt`、`manager.log`和 `host-manager.log`等日志文件,可以快速定位和解决问题,确保Tomcat服务器的稳定运行。掌握这些日志解析技巧,可以显著提高运维和开发效率。
954 13
|
9月前
|
缓存 Java 编译器
|
11月前
|
SQL 关系型数据库 MySQL
MySQL事务日志-Undo Log工作原理分析
事务的持久性是交由Redo Log来保证,原子性则是交由Undo Log来保证。如果事务中的SQL执行到一半出现错误,需要把前面已经执行过的SQL撤销以达到原子性的目的,这个过程也叫做"回滚",所以Undo Log也叫回滚日志。
605 7
MySQL事务日志-Undo Log工作原理分析
|
9月前
|
SQL 存储 关系型数据库
简单聊聊MySQL的三大日志(Redo Log、Binlog和Undo Log)各有什么区别
在MySQL数据库管理中,理解Redo Log(重做日志)、Binlog(二进制日志)和Undo Log(回滚日志)至关重要。Redo Log确保数据持久性和崩溃恢复;Binlog用于主从复制和数据恢复,记录逻辑操作;Undo Log支持事务的原子性和隔离性,实现回滚与MVCC。三者协同工作,保障事务ACID特性。文章还详细解析了日志写入流程及可能的异常情况,帮助深入理解数据库日志机制。
1137 0