记一次线上应用宕掉的问题分析
By: Date: 2022年1月27日 Categories: 程序 标签:

前几天生产服务器上部署的应用出现了故障,搞的兄弟们惊出一身冷汗。几十个节点的应用正一个接一个的挂调,持续下去会直接导致提供给外部的高并发服务不可用,影响一系列上下游业务正常进行。在观察后台的监控后发现,CPU正常,但内存在一个很短的时间内出现飙高的情况。观察了几台挂掉的机器,都是相同的问题。为了在出现问题后为不影响线上业务,让同事第一时间对出现问题的应用进行了重启。重启之后,服务又稳定正常运行,事后我们对线上的问题进行了具体的分析。

其实出现上面的问题,内存在很短的时间内被占满,大体上可以想到一般都是由于应用中有大量的对象被创建,这时候创建的速度超过了回收的速度,使得内存当中对象没有及时被清理导致,而不太可能出现的是内存泄露,因为内存泄露的时间一般持续的时间会比较长。问题出现到现在过去了几天,没保留监控的截图,但是问题产生的dump文件还在,就由这个dump文件,来大概看看问题到底出在了哪里。

检查启动参数配置

首先需要检查下我们的JVM启动参数,检查这个是因为线上环境刚做了服务器的迁移,担心应用的配置更新有遗漏。

-Xms5g -Xmx5g -XX:MaxPermSize=256m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/export/Logs

解释一下:
-Xms5g JVM初始分配堆内存大小为5G
-Xmx5g JVM最大允许分配的堆内存大小为5G
-MaxPermSize JVM最大允许分配的非堆内存,设置为256M
HeapDumpOnOutOfMemoryError 表示在JVM发生OOM的时候,自动的生成Dump文件,可以用于根因分析。

我们的容器规格是4C8G,对于我们的应用,设置5G的堆内存绝对是够用的,没什么问题。

MAT内存分析

拿到应用转储的dump,一看大小竟然5个多G,既然是内存问题,直接用MAT来分析下。

MAT 全称是Memory Analyzer Tool,下载地址:http://www.eclipse.org/mat/downloads.php

这里我们项目使用的jdk是1.8,所以我们下载的MAT版本是 MemoryAnalyzer-1.8.1 这个版本,它更新的版本就需要jdk9以上的支持了。

当然要打开这5个G的dump,我们还得来修改下MAT的启动参数,在安装目录下找到 MemoryAnalyzer.ini 文件,修改最后一行的堆内存大小配置为 -Xmx8224m,当然了 大小可以自己根据情况设。

首先使用MAT打开我们下载下来的dump文件,选择第一个Leak Suspects Report(泄露可疑报告) ,等待MAT工具分析完成,这个过程稍微会有一点慢。

接下来,可以看到对于我们这个大的dump的一个分析的总览:

mat-overview

这里先来翻译一下:
下面的Actions中同时也提供了更具体的维度的分析选项:
Histogram:通过直方图可以列出内存中每个实例的数量,以及大小。
Dominator Tree:用支配树列出最大的对象,以及使他们保持活动状态的对象。
Top consumers:顶级消费者,按类和包分组列出最大的对象。
Duplicate Classes:重复类,检测由多个加载器加载的类。

Reports中提供如下两个选项:
Leak Suspects:分析泄露的原因以及系统概述的报告。
Top Components:列出大于总堆1%的组件的报告。

Step By Step中有一项:
Component Report:组件报告,分析属于公共根包或类加载器的对象。

首先,我们先来看一下Histogram

histogram

这里面包含了Class Name,Objects,Shallow Heap,Retained Heap几列,说明下:
Shallow Heap:浅堆,是指这个对象实际占用的堆大小。
Retained Heap:保留堆,一般会大于或者等于Shallow Heap的总和,也就是这个对象被GC之后,所能回收的内存大小。
这里我们可以重点来关注Shallow Heap。按照这列排序,可以看到排在第三行的是com.mysql.jdbc.ByteArrayRow,这个总共占用了4.3G的空间,看到这里就已经隐隐约约的看到了一些问题,继续往下看。

Dominator Tree维度分析中,我们通过Retained Heap进行排序,我们看到内存占用排在前面的都是这个,com.mysql.jdbc.JDBC4PreparedStatement,前面的9项每一个都占用空间近500M,占10%,相加总和就占用了90%的空间,可见问题的原因就是出在了这里。可以推测是数据库查询了大量的数据,并将对象的实例放在了内存当中,这些实例的数量和大小占据了90%的堆空间,使得应用产生了OOM。

可以继续点开看这个对象所包含的内容。

同时,我们也能看到在com.mysql.jdbc.JDBC4PreparedStatement实例的属性中,有一项originalSql就是本次查询的SQL。

点上面的齿轮,可以看到线程信息。

thread

到这里,其实已经很清楚了,因为是分库分表,所以在查询该表的时候,使用了多个线程去查询,所以我们查看线程信息的时候会发现有很多的线程。因为是在新的线程里执行查询的方法,这里我们就定位不到对应在我们项目中的代码位置。

倘若是在一个线程中做的操作,那么我们可以像上面图中这样,在线程中查看到它的调用链,并且可以看到具体的调用方法,对于我们定位到具体的代码还是很有帮助的。

即使这样,根据上面所获取的信息,其实我们已经知道了在哪个位置产生的问题。结合对应的代码,我们的问题也就清晰了,是因为在分库分表查询的时候,因为只给了查询条件的两个参数,而没有使用分页查询,导致开了10个线程查询分库分表时,返回了大量的数据在内存中。

已经知道了问题,那再来看看Leak Suspects的分析报告吧。

这里也给出了内存分析后的结果,最大内存占用依然是com.mysql.jdbc.JDBC4PreparedStatement。

这些每一个项都可以点进去看,所以MAT已经从各个维度帮助我们很好的定位到了问题。其他的功能就不细说了大概截几个图片来简单看看。

所以,这里已经能看出MAT的强大了,他可以帮我们看到对象的引用关系,对象引用了什么对象,又被什么对象引用了,都会很详细的展示出来,所以一般遇到内存问题,比如OOM的问题直接上MAT就对了。

当然了,其实还有一些其他的辅助工具,也都可以用,后面我们具体遇到了再细说。

发表回复

您的电子邮箱地址不会被公开。