[实战]定位线上OOM/OutOfMemoryError导致的宕机问题

Wanxp

2021-02-03

324

背景

线上宕机是一种非常严重的问题，如果线上没有服务冗余就是生产事故。所以定位问题，确保下次不会再出现此类问题。宕机的原因有很多种，最为常见的是OOM异常，即OutOfMemoryError。下面的一次定位线上问题的过程，记录以防后续又再次遇到能够及时反馈定位问题。

环境

版本

ubuntu20.04
jdk1.8u172
springboot2.3.5.RELEASE

线上工具

jdk 包含jcmd, jps
netstat
ssh, scp

本地工具

jdk 包含jvisualvm
ssh, scp

告警信息

elk-log日志

Request processing failed; nested exception is java.lang.RuntimeException: com.google.gson.JsonParseException: Failed parsing JSON source: JsonReader at line 1 column 138099214 path $.hits.hits[28112]._source.items[0].actualUnitVolume to Json] with root cause
java.lang.OutOfMemoryError: Java heap space

线上环境确认运行状态

以下内容均在线上服务器操作

确认java版本

java -version

输出java版本

Java HotSpot(TM) 64-Bit Server VM (build 25.131-b11, mixed mode)

确认java程序的pid

jps

输出

4397 Jps

看来是没有权限，使用管理员权限

sudo jps

输出

sudo: jps: command not found

java目录没有加入管理员的环境变量里，那就使用全路径的方式，先定位jdk路径

which java

得到jdk的路径

/opt/jdk1.8.0_131/bin/java

接下来使用超级管理员运行完整路径的命令

sudo /opt/jdk1.8.0_131/bin/jps

12917 jar
31045 jar

命令无法看出具体是哪个服务，更换为netstat，从服务端口确定程序pid为31884

sudo netstat -nlp

tcp6     101      0 :::8800                 :::*                    LISTEN      31884/java

获取启动信息

查询jcmd 获取当前pid的具体能使用的属性，下面的31884替换成你自己的pid

sudo /opt/jdk1.8.0_131/bin/jcmd 31884 help

输出内容

31884:
The following commands are available:
JFR.stop
JFR.start
JFR.dump
JFR.check
VM.native_memory
VM.check_commercial_features
VM.unlock_commercial_features
ManagementAgent.stop
ManagementAgent.start_local
ManagementAgent.start
GC.rotate_log
Thread.print
GC.class_stats
GC.class_histogram
GC.heap_dump
GC.run_finalization
GC.run
VM.uptime
VM.flags
VM.system_properties
VM.command_line
VM.version
help

查看运行时间

sudo /opt/jdk1.8.0_131/bin/jcmd 31884 VM.uptime

31884:
1278530.858 s

查看启动命令

sudo /opt/jdk1.8.0_131/bin/jcmd 31884 VM.command_line

31884:
VM Arguments:
jvm_args: -Xms1024m -Xmx2048m
java_command: ****-elasticsearch-service.jar --spring.profiles.active=prod
java_class_path (initial): ****-elasticsearch-service.jar
Launcher Type: SUN_STANDARD

原来是最大堆内存设置为2048mb，设置过小导致
4. 查看启动参数

sudo /opt/jdk1.8.0_131/bin/jcmd 31884 VM.flags

31884:
-XX:CICompilerCount=3 -XX:InitialHeapSize=1073741824 -XX:MaxHeapSize=2147483648 -XX:MaxNewSize=715653120 -XX:MinHeapDeltaBytes=524288 -XX:NewSize=357564416 -XX:OldSize=716177408 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseFastUnorderedTimeStamps -XX:+UseParallelGC

获取运行状态

获取当前线程信息

sudo /opt/jdk1.8.0_131/bin/jcmd 31884 Thread.print >> ~/elasticsearch-service-down-thread.txt

获取当前内存至本地文件

sudo /opt/jdk1.8.0_131/bin/jcmd 31884 GC.heap_dump ~/elasticsearch-service-down-dump.bin

本地分析

以下内容均在本地操作

将文件下载至本地

scp username@ip:~/elasticsearch-service-down-thread.txt ./
scp username@ip:~/elasticsearch-service-down-dump.bin ./

jvisualvm分析
打开jvisualvm

jvisualvm

加载文件elasticsearch-service-down-dump.bin
3. 利用可视化工具jvisualvm获取堆内存对象情况。
通过log日志可知，是gson反序列化所致，字符串处理过程中的内存分配不足，所以重点查看是否是字符串长度超长导致的内存问题，但最终通过OQL没有找到内存的问题字符串。而且elasticsearch-service-down-dump.bin大小为160MB, 远小于设置的最大堆内存量，存在两种情况，一是内存已经被回收，而是总物理内存不足。但总物理内存

本地模拟重现

使用上面第3节"查看启动命令"得到的启动命令在本地运行对应的jar包

java -jar -XX:CICompilerCount=3 -XX:InitialHeapSize=1073741824 -XX:MaxHeapSize=2147483648 -XX:MaxNewSize=715653120 -XX:MinHeapDeltaBytes=524288 -XX:NewSize=357564416 -XX:OldSize=716177408 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseFastUnorderedTimeStamps -XX:+UseParallelGC ****-elasticsearch-service.jar --spring.profiles.active=prod

模拟触发场景
模拟用户的请求，发现还是没有触发OOM Error, 所以此次还需从另外一个方向入手。
解决方法
增加java 启动参数将OOM内存及时输出文件，然后采取具体定位是哪部分内存没有回收。

最后

总结

问题已经定位时已经是项目处于宕机，且gc已经完成，所以最后内存已经是正常状态，以及线程也是正常状态，所以具体的内存内容无法得到。
但是通过查log日志信息，可以得知是字符串反序列化成对象时内存溢出，这块功能是只有spring-data-jest请求elasticsearch使用gson反序列化所致。虽然是这个地方导致，但并非是根本原因。服务器CPU使用率以及物理内存的使用量监控记录来看，也并非是服务器本身的原因。从综上分析是当前java程序运行过程中

解决方案:

在启动命令中加入启动参数，HeapDumpOnOutOfMemoryErrord当程序出现OOM时自动备份堆内存文件,HeapDumpPath指定堆内存的生成位置(必须是存在的位置,该参数不会生成不存在的路径),下面的"/usr/local/log/"可以替换你自己的路径

-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/usr/local/log/

增加最大堆内存

-Xmx3069m

重新发布项目