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<pid>.hprof

生产环境一般都会配置堆溢出时自动生成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识堂 ,作者李立敏