性能分析之JVM堆外内存引发Linux OOM Killer_系统日志

    连续三天,晚上在执行一个业务场景持续几个小时之后,就开始连续报错。

    服务器连不上了。但在报错的一开始,并不是全部都报错,而是有部分是可以成功的,但是过一段时间之后,所有业务都报错了。

    次日来看,发现进程不见了。

    本来以为是进程崩溃退出了,那日志中应该留下来些证据。

    但是打开了日志查看了一下,没有任何异常信息。

    前两天只听团队成员说了,我没太在意,先让他们查。

    可是连续三天都出现,并且他们没有查出任何错误信息,这就不正常了。

    一个兄弟说FGC影响了,可是过滤了GC LOG中的Full GC一看,似乎频繁并没有那么频繁,三分钟一次,在这样的压力还算正常。并且E和O区是可以回收到正常的水平的。

    听到这里,我觉得有点不正常了。

    所以我就登录zabbix上去看了一下主机资源。

 

性能分析之JVM堆外内存引发Linux OOM Killer_错误信息_02

    红框内的是出现问题的时间段。看到这里似乎明白了为什么并不是所有业务都失败。因为内存还有上升的这个阶段。但是为什么降到底之后又上去,再次降到底呢?先看一下拓扑图。

性能分析之JVM堆外内存引发Linux OOM Killer_java_03

    两个主机,四个进程,既然进程都没了,应该不是一块没的,要不然不会还有业务可以成功。

    翻了一下应用日志,确实没有什么和进程消失相关的错误信息。

    既然是进程没了,日志也没信息,那下一步是什么呢?就是看dmesg了。系统日志总有些信息吧。进程死了无非就那么几个地方能看到。

  1. 应用日志;2. 出dump;3. 系统日志。

    在这里提醒一下,最好直接运行dmesg命令,而不是去看/var/log/dmesg文件。因为命令中会把其他message也放进去,会全一点。

    查看了dmesg之后,发现如下信息:

性能分析之JVM堆外内存引发Linux OOM Killer_java_04

    从时间上来算一下。系统运行时间41.45天,确实和第一个图上的21:30的时间对应得上。从这里来看是6341进程被杀了。

    再看第二个图:

性能分析之JVM堆外内存引发Linux OOM Killer_java_05

    再来算一下时间。41.55天,和第一个图上的11:45能对得上。

    看来是OOM Killer主动把这两个进程给杀了。从下面的信息来看是这两个进程消耗linux主机的物理内存和虚拟内存太大,以致于把内存都给消耗光了,最后OOM Killer就站出来主持公道了:小子挺横呀,老子分给你了一亩三分地,不好好呆着,敢来抢地盘,干它!

于是就真的被kill了。

    既然知道了内存消耗得多,那这个场景就好复现了。接着用原场景测试。看下java进程的内存,java的内存分成堆内堆外。 因为是操作系统的OOM Killer干掉的,所以基本上可以排除堆内的内存导致的。因为堆是有限制的嘛。不过还是搂一眼,反正看一眼也不会怀孕。

性能分析之JVM堆外内存引发Linux OOM Killer_系统日志_06

    看了之后,三个字:没毛病!

    既然这样,那就是堆外喽。堆外嘛,无非就是NIO、线程栈之类的。首先这个不好抓。但是开发很清楚自己干了什么事,有源码拿来翻翻,也能翻出来。

    打个threaddump看看。

性能分析之JVM堆外内存引发Linux OOM Killer_错误信息_07

    哟,怎么这么多线程?并且也看到了开发的包名。

    把这个路径给了开发之后,让他们翻翻这一段的源码,看到如下内容:

    Thread thread = new Thread();


    开发这才知道是为啥有这么多新创建的线程。

    于是拿回去改去了。


    对于性能分析来说,技巧是一方面,但是知道什么时候去看什么东西,那是非常非常重要的。