P0事故安排上了
原来以为内存溢出这种事情只会发生在书本上,没想到在我们生产环境发生了,而且是618,P0事故安排上了。先回顾一下内存溢出排查的基本思路,然后再来复盘一下内存溢出发生的原因
内存溢出排查
我们先来了解一下Java堆的组成机构。对于大多数应用来说,Java堆(Java Heap)是Java虚拟机锁管理的内存中最大的一块。Java堆是所有线程共享的一块内存区域,在虚拟机启动时创建。此内存区域的唯一目的就是存放对象实例,几乎所有的对象实例都在这里分配内存
「堆的结构如下」
「新生代老年代的具体划分比例如下」
「分代的主要作用就是为了更高效的管理内存」
内存泄漏和内存溢出是2个不同的概念
内存泄漏:对象已经不使用了,但是还占用着内存空间,没有被释放 内存溢出:堆空间不够用了,通常表现为OutOfMemoryError,内存泄漏通常会导致内存溢出
使用Java VisualVM分析排查
「我们可以通过jdk自带的jvisualvm命令来分析堆的使用情况」
我们写一个程序,来演示内存不断增加的场景
- public class OomDemo {
- private static final int NUM = 1024;
- public static void main(String[] args) throws InterruptedException {
- List<byte[]> list = Lists.newArrayList();
- for (int i = 0; i < NUM; i++) {
- TimeUnit.SECONDS.sleep(1);
- list.add(new byte[NUM * NUM]);
- }
- }
- }
「命令行中执行jvisualvm即可弹出图形界面,我们可以连接到本机上的程序,也可以连接到远程机器,还可以分析生成快照文件等」。
可以清晰的看到堆空间在不断上涨,用抽样器分析一下内存不断上涨的源头在哪里?
「好家伙,byte数组居然占用了这么多内存」
如果此时你还看不出程序哪里有问题,到监视这个Tab点击堆Dump这个按钮,会生成一个堆的快照,然后分析这个dump文件即可
byte数组实例很少,但是占用内存很多,再看一下具体的引用
可以看到在ArrayList中。
最后推荐一个插件Visual GC,可以清晰的看到堆的使用情况以垃圾收集信息。
点击工具选中插件即可
当然你可以通过jmap命令生成heapdump文件,然后用其他工具分析
- jmap -dump:file=文件名字 进程id
使用Eclipse Memory Analyzer分析
Java VisualVM只提供了一些基本的功能,堆中各种对象的大小和实例数。以上面的例子为例,你只能排查到ArrayList占用了大量的内存,这个ArrayList在哪,你也不知道
所以我们一般不使用Java VisualVM来分析,而是使用Eclipse Memory Analyzer来分析
Eclipse Memory Analyzer下载地址:https://www.eclipse.org/mat/downloads.php
还是上面的程序,我们启动时设置如下参数,让程序内存溢出时自动生成Dump文件
- -Xmx30m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/Users/peng
-Xmx30m:最大堆内存为30m -XX:+HeapDumpOnOutOfMemoryError:当JVM发生OOM时,自动生成DUMP文件。-XX:HeapDumpPath:指定文件路径,例如:-XX:HeapDumpPath=${目录}/java_heapdump.hprof。如果不指定文件名,默认为:java_pid
生产环境一般都会配置堆溢出时自动生成DUMP文件图片当内存溢出的时候自动生成了一个文件,java_pid28598.hprof
「用Eclipse Memory Analyzer打开这个文件,可以很清晰的看到总共使用的内存,以及各个对象占用的内存」,如下图
总共使用的内存为26.8M Thread对象占用了26M ZoneInfoFile对象占用了157.8KB 其他对象占用了696.7KB
点击Leak Suspects按钮查看具体的内存泄露报告
分析出来有问题的部分只有一处(例子太简单的缘故,很多时候会分析出来多处)
「main线程占用了97.21%的内存空间」
「点击标红按钮,查看引用关系,可以很清晰的看到是由于main线程中ArrayList中放了26个byte数组造成的」
「另外可以很清晰的看到内存溢出时代码的执行位置,排查问题非常方便」
事故复盘
先来看一下事故发生前和事故发生后JVM的情况,我们新生代用的是ParNew垃圾收集器,老年代用的是CMS垃圾收集器
13:00-13:10这段时间的情况,系统正常运行
每分钟GC暂停时间(绿色部分是CMS,黄色部分是ParNew)
每分钟GC次数和GC平均耗时(绿色部分是CMS,黄色部分是ParNew)
新生代和老年代的占用情况
「可以看到问题发生之前老年代已经设置的不合理了,偏小了」。
14:00-14:10这段时间的情况,14:06系统内存溢出
14:00活动开始,14:05之后每分钟垃圾回收暂停的时间过长,都达到30s了
老年代垃圾回收的时间飙升
实在没有可回收的了,最终老年代被占满,内存溢出
分析dump文件
运维配置了上面说的2个参数,内存溢出时生成了dump文件,用Eclipse Memory Analyzer打开分析一波
总共1.9G,ThreadPoolExecutor占用了918.8MB,我们来看看ThreadPoolExecutor这个线程池里面到底放了些啥
分析报告指出的第一个问题就是ThreadPoolExecutor里面的东西太大了,占了总内存的47.45%了,点击如下按钮,查看引用链路
好家伙,线程池占用了900多m空间,里面用LinkedBlockingDeque存放待执行的任务
「队列的能存放的最大数量是10000,目前放了883个任务,这个队列的长度设置的也忒大了把!」
继续点下去,就能看到队列中存的具体对象,是个DTO。看包名就猜到是中间件团队将这个DTO放到线程池中
大概逻辑如上图,中间件团队会通过一个agent拦截应用中方法的执行,并将入参和返回值打印在日志中,flume收集日志后给链路平台,监控平台提供数据。
方法每执行一次打印一次日志,但是日志的打印是异步化的,将参数和返回值封装成任务,放到线程池中执行。由于618方法被高频调用,而其中一类DTO对象很大(一个对象6,7m),任务一旦堆积,很快就是OOM。「因为队列的最大值被设置为10000,但是当放了883个任务的时候已经OOM了」
本文转载自微信公众号「Java识堂」,可以通过以下二维码关注。转载本文请联系Java识堂公众号。