JVM异常导致程序中断问题探讨(修订)

前言

目前项目中遇到的异常信息
1. 一种是因为内存空间分配不足导致 OutOfMemory
2. 另外一种是JVM报错信息 exception happened outside interpreter
后续如果出现JVM相关问题再进行追加

报错分析

首先需要明确的是,如果项目中出现问题, 那一定是有迹可循的, 诸如程序异常, 那么一定会留下Error堆栈信息, 如果看不到那一定是被某个地方捕获,从而没有抛出在控制台上, 像服务异常中断, 那一定会留下hs_error_pidxxx.log之类的文件,同时会留下中断那一时刻的内存信息, 再比如像内存溢出, 你会在垃圾回收的日志中发现内存不断增大, GC频率变高, 同时会存在一些回收不掉的内存空间. 最后达到配置的堆内存上限, 程序就会挂掉, 如果你配置了-XX:+HeapDumpOnOutOfMemoryError 那将会抛出内存文件方便你进行分析.

OutOfMemory

这个基本上属于常见的系统挂掉的问题了, 通常是由于JVM内存空间配置参数过小导致, JVM会通过每次GC调整到自己需要的大小,直到超出系统承受的范围,或者堆空间设置上限
对于OutOfMemory有两种解释,因为表象一样,都是因为可分配空间不足

内存泄露 : 申请内存后, 无法释放已申请的内存空间,无法被清理掉. 内存空间会无上限的增长. 比如栈溢出就是栈空间满了, 你还要再入栈, 那必然会溢出(上溢). 栈为空的情况下, 出栈则也会溢出(下溢). 可分配空间不足, 则溢出.等等此类
内存溢出: 申请内存后,没有足够的空间进行使用, 从而抛出异常

实例一

线上环境:
配置:
服务器: linux 16核 32G内存 (通过lscpu查询)
JVM参数: -Xms256m -Xmx1024m -Xmn256m即堆内存初始大小256m(默认内存64分之一), 堆内存最大为1024m(默认内存4分之一), 新生代最大为256m, 同理可得老年代的大小为768m 其他空间为系统默认大小
现象:
程序部署上去后, 内存空间不断的增大, 通过jstat -gc pid 可以发现步长十分大,且GC频繁, 老年代一直在增大, GC并不能回收掉系统空间, 并且每次执行调度任务的时候, cpu超频执行, 执行1000%.
可以得出结论: 肯定是因为某些代码一直在存储大对象, 且一直保持引用关系, 导致这部分空间一直不能被释放. 这时有两个方向, 一个cpu占用最大的线程分析线程执行代码, 另外一个分析堆空间信息, 因为是代码复杂,且堆空间一直不能释放所以这里选择分析堆空间
定位问题:
转储线上内存堆栈信息, (jmap-dump:format=b,file=/opt/soft/xx.hprof). 使用MAT分析内存, 一般会直接帮你定位堆空间占用过大的对象, 以及线程信息. 通过跟踪我们即可定位到问题

实例二

配置:
服务器: linux 16核 32G内存 (通过lscpu查询)
JVM参数: -Xms256m -Xmx1024m -Xmn256m即堆内存初始大小256m(默认内存64分之一), 堆内存最大为1024m(默认内存4分之一), 新生代最大为256m, 同理可得老年代的大小为768m 其他空间为系统默认大小
现象
放置到线上环境后, 经常出现

java.lang.OutOfMemoryError: GC overhead limit exceeded
java.lang.OutOfMemoryError: Heap out memory
定位问题
转储堆栈信息分析, 由Dominator_tree 分析得到目前, 内存占用最大的几个对象,及引用地址

共分三个大引用:
WorkSignWarningTask
AccidentWorkTask
CemsStatisticsTask
再具体分析这三个引用下大对象信息

前两个是因为存储大量HourAirDto, 后者是因为存在大批CemsStatisticsDetail
问题现在就找到了, 定位到具体代码对这三个对象的处理上就可以解决问题

exception happened outside interpreter

实例一

配置:
服务器: Windows Server 2012 R2 8核 16G
初始JVM参数: -Xms256m -Xmx1024m -Xmn256m
现象:
服务部署上去后, 每隔一段时间系统就会自行挂掉, 同时抛出一个error日志和内存信息(只能通过windows的vs才能分析).
定位问题:
这个问题表示异常发生在外部, 起初查阅了各种资料和问题, 都没有对当前的一个具体解释. 从抛出的error日志也分析不出具体的问题,日志如下:

#
# A fatal error has been detected by the Java Runtime Environment:
#
#  Internal Error (sharedRuntime.cpp:834), pid=5500, tid=668
#  fatal error: exception happened outside interpreter, nmethods and vtable stubs at pc 0x0000000002ad4750
#
# JRE version: Java(TM) SE Runtime Environment (8.0_45-b15) (build 1.8.0_45-b15)
# Java VM: Java HotSpot(TM) 64-Bit Server VM (25.45-b02 mixed mode windows-amd64 compressed oops)
# Core dump written. Default location: E:\jointframe-enterprise-datasync-garbage\bin\hs_err_pid5500.mdmp
#
# If you would like to submit a bug report, please visit:
#   http://bugreport.java.com/bugreport/crash.jsp
#

---------------  T H R E A D  ---------------

Current thread (0x0000000028caa800):  JavaThread "NettyClientWorkerThread_4" [_thread_in_Java, id=668, stack(0x0000000031fb0000,0x00000000320b0000)]

Stack: [0x0000000031fb0000,0x00000000320b0000]
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V  [jvm.dll+0x32b57a]
V  [jvm.dll+0x279873]
V  [jvm.dll+0x27a509]
V  [jvm.dll+0x2717a6]
V  [jvm.dll+0x228bfe]
V  [jvm.dll+0x297d60]
V  [jvm.dll+0x32b408]
C  [ntdll.dll+0x9398d]
C  [ntdll.dll+0x593a7]
C  [ntdll.dll+0x92b1a]
C  0x0000000002ad4750

Compilation events (10 events):
Event: 1936.996 Thread 0x000000001e6b7000 16587       3       org.bson.types.ObjectId::short1 (6 bytes)
Event: 1936.996 Thread 0x000000001e6b7000 nmethod 16587 0x0000000004e24a90 code [0x0000000004e24be0, 0x0000000004e24d10]
Event: 1936.998 Thread 0x000000001e6b7000 16588       3       org.bson.types.ObjectId::short0 (3 bytes)
Event: 1936.998 Thread 0x000000001e6b7000 nmethod 16588 0x0000000005338890 code [0x00000000053389e0, 0x0000000005338b10]
Event: 1939.305 Thread 0x000000001e6b7000 16589       3       com.fasterxml.jackson.databind.introspect.AnnotatedConstructor::call (12 bytes)
Event: 1939.306 Thread 0x000000001e6b7000 nmethod 16589 0x0000000003191250 code [0x00000000031913c0, 0x0000000003191668]
Event: 1939.308 Thread 0x000000001e6b7000 16590       3       com.fasterxml.jackson.core.base.ParserMinimalBase::hasTokenId (34 bytes)
Event: 1939.308 Thread 0x000000001e6b7000 nmethod 16590 0x000000000467e7d0 code [0x000000000467e940, 0x000000000467ec50]
Event: 1939.310 Thread 0x000000001e6b7000 16591       3       com.fasterxml.jackson.core.base.ParserBase::getCurrentName (45 bytes)
Event: 1939.311 Thread 0x000000001e6b7000 nmethod 16591 0x000000000467e150 code [0x000000000467e2c0, 0x000000000467e6d0]

GC Heap History (10 events):
Event: 1649.860 GC heap before
{Heap before GC invocations=34 (full 5):
PSYoungGen      total 683520K, used 603296K [0x0000000780000000, 0x00000007af480000, 0x00000007c0000000)
eden space 597504K, 100% used [0x0000000780000000,0x00000007a4780000,0x00000007a4780000)
from space 86016K, 6% used [0x00000007aa080000,0x00000007aa628030,0x00000007af480000)
to   space 88576K, 0% used [0x00000007a4780000,0x00000007a4780000,0x00000007a9e00000)
ParOldGen       total 174080K, used 137943K [0x00000006c0000000, 0x00000006caa00000, 0x0000000780000000)
object space 174080K, 79% used [0x00000006c0000000,0x00000006c86b5c38,0x00000006caa00000)
Metaspace       used 90135K, capacity 94794K, committed 94976K, reserved 1132544K
class space    used 11092K, capacity 11918K, committed 12032K, reserved 1048576K
Event: 1649.870 GC heap after
Heap after GC invocations=34 (full 5):
PSYoungGen      total 603648K, used 5968K [0x0000000780000000, 0x00000007af100000, 0x00000007c0000000)
eden space 597504K, 0% used [0x0000000780000000,0x0000000780000000,0x00000007a4780000)
from space 6144K, 97% used [0x00000007a4780000,0x00000007a4d54040,0x00000007a4d80000)
to   space 86016K, 0% used [0x00000007a9d00000,0x00000007a9d00000,0x00000007af100000)
ParOldGen       total 174080K, used 137951K [0x00000006c0000000, 0x00000006caa00000, 0x0000000780000000)
object space 174080K, 79% used [0x00000006c0000000,0x00000006c86b7c38,0x00000006caa00000)
Metaspace       used 90135K, capacity 94794K, committed 94976K, reserved 1132544K
class space    used 11092K, capacity 11918K, committed 12032K, reserved 1048576K

发生问题的时候第一反应是堆空间不足, 但是调试程序时观察GC信息及崩溃时现象, 可以排除掉:

GC并不存在任何异常, 同时发生崩溃并没有生成OutOfMemory日志, 调试模式默认开启了-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=%BASE_DIR%\logs\java_heapdump.hprof
发生崩溃时, cpu及内存并没有峰值变化, 和正常运行保持一致. 就是突然就中断了
通过以上日志分析发生崩溃是, 新生代/老年代/堆空间大小/直接内存/元空间都没有异常. 且没有发生溢出
分析堆栈信息及线程也得不到有用信息, 只能知道是运行日志提示的current thread 执行时, 突然中断

结论: 现在已经排除是JVM配置及系统饱和导致的. 而报错提示发生在外部, 不得不让人怀疑是因为Java程序的问题, 通过更新Java版本, 问题得以解决

目录CONTENT

JVM异常导致程序中断问题探讨(修订)

前言

报错分析

OutOfMemory

实例一

实例二

exception happened outside interpreter

实例一

评论区