JVM实战—13.OOM的生产案例

技术分享 17小时前 0 999+

关注

大纲

1.每秒仅上百请求的系统为何会OOM(RPC超时时间设置过长导致QPS翻几倍)

2.Jetty服务器的NIO机制如何导致堆外内存溢出(S区太小 + 禁NIO的显式GC)

3.一次微服务架构下的RPC调用引发的OOM故障排查实践(MAT案例)

4.一次没有WHERE条件的SQL语句引发的OOM问题排查实践(使用MAT技巧)

5.每天10亿数据的日志分析系统的OOM问题排查(堆内存太小 + 递归要谨慎)

6.类加载器过多引发OOM问题排查(服务假死自己恢复+ top判断 + OS杀进程)

7.数据同步系统频繁OOM内存溢出的排查(时不时OOM+内存泄露+MAT排查)

8.线上系统的JVM参数优化、GC问题定位排查、OOM分析解决总结

1.每秒仅上百请求的系统为何会OOM(RPC超时时间设置过长导致QPS翻几倍)

(1)案例背景

(2)系统发生OOM的生产现场

(3)Tomcat的基本工作原理

(4)异常日志

(5)不要忘了一个关键的JVM参数

(6)对内存快照进行分析

(7)系统每秒QPS才100

(8)为什么处理一个请求需要4秒

(9)对系统进行优化

(1)案例背景

在这个案例中，一个每秒仅仅只有100+请求的系统却因频繁OOM而崩溃。这个OOM问题会涉及：Tomcat底层工作原理、Tomcat内核参数的设置、服务请求超时时间。

(2)系统发生OOM的生产现场

某一天突然收到线上系统的一个报警，说系统发生了异常。一看异常信息让人大惊失色，居然是OOM问题。这个问题不得了，因为一旦JVM发生OOM，将会导致系统直接崩溃。OOM代表的是JVM本身已经没办法继续运行了。因此马上登录到系统的线上机器去查看对应的日志。

需要注意：一旦收到系统OOM报警，或者有人突然反馈说线上系统崩溃了。第一件事情一定是登录到线上机器去看日志，而不是做别的事情。当时在机器的日志文件中看到类似下面的一句话：

Exception in thread "http-nio-8080-exec-1089" java.lang.OutOfMemoryError: Java heap space

根据Tomcat的底层工作原理可知：这里的http-nio-8080-exec-1089指的是Tomcat的工作线程，而java.lang.OutOfMemoryError: Java heap space指的是堆内存溢出。

所以连起来看，这段日志的意思就是：Tomcat的工作线程在处理请求时需要在堆内存里分配对象。但发现堆内存满了，且没办法回收任何一点多余的对象，所以OOM。

(3)Tomcat的基本工作原理

一.项目部署的发展

很久以前我们写的系统是部署在Tomcat中的，我们会在IDEA等开发工具里写一堆的Servlet。然后打包放入Tomcat，之后再启动Tomcat。接着我们会访问Tomcat监听的一个端口号比如8080，然后系统的功能就可以运行起来了。

后来随着技术发展，不再写Servlet这么原始的东西了，有一些类似Spring MVC的框架把Servlet封装起来，于是就基于Spring MVC框架去开发。

再后来技术越来越先进，出现了Spring Boot，可以把Tomcat之类的Web容器都内嵌在系统里，再后来甚至是基于Spring Cloud去开发分布式的系统。

二.项目部署在Tomcat的处理请求流程

如下图示，这是一个最基本的Web系统部署在Tomcat中运行的架构图：

上面这个图表示：基于Spring Cloud、Spring Boot、Spring MVC等技术，写好一套系统。然后打包后放入线上服务器中部署的Tomcat目录下，接着启动Tomcat。Tomcat会监听一个默认8080的端口号，之后我们就可以通过浏览器对这个机器上的Tomcat发起HTTP请求了。

接着Tomcat会监听8080端口收到请求，通常Tomcat会把请求交给Spring Web MVC等框架去处理。这类框架一般都会在底层封装Servlet/Filter之类的组件去处理请求，如下图示：

然后类似Spring MVC框架的Servlet组件，就会根据请求的路径去找到处理这个请求的Controller组件。

三.Tomcat究竟是什么

如果我们把写好的系统放入Tomcat目录中，然后启动Tomcat。那么启动的Tomcat本身就是一个JVM进程，因为Tomcat是由Java写的。

如下图示，Tomcat自己就是一个JVM进程，我们写好的系统只不过是一些类而已。这些类被Tomcat加载到内存里，然后由Tomcat来执行。

四.Tomcat如何监听8080端口上收到的请求

很简单，因为Tomcat有自己的工作线程。Tomcat有很多自己的工作线程，少则一两百个，多则三四百个。然后从8080端口上收到的请求会被均匀分配给这些工作线程去处理。这些工作线程收到请求后，就负责调用Spring MVC框架的代码。Spring MVC框架又负责调用我们写好的代码，比如一些Controller类，所以最终的运行流程如下图示：

(4)异常日志

接着查看当时线上系统的日志，发现如下异常：

Exception in thread "http-nio-8080-exec-1089" java.lang.OutOfMemoryError: Java heap space

http-nio-8080-exec-1089其实就是上图中的Tomcat工作线程，它会负责调用Spring MVC及Controller、Service、DAO等代码。所以它发现运行时堆内存不够，就会抛出堆内存溢出的异常。

(5)不要忘了一个关键的JVM参数

一旦发现线上系统发生了OOM内存溢出异常：

第一步是查看日志确定OOM类型和线程

首先需要确定具体的溢出类型，看看到底是堆内存溢出、还是栈内存溢出、或者是Metaspace内存溢出。然后查找哪个线程运行代码时内存溢出，因为Tomcat运行时不仅有自己的工作线程，也有我们创建出的一些线程。

注意：在部署系统上线的时候务必要设置HeapDumpOnOutOfMemoryError参数，这个参数会在系统OOM内存溢出时导出一份内存快照到指定的位置。

第二步是排查和定位OOM内存溢出问题

主要就是根据系统OOM内存溢出时自动导出的内存快照，通过MAT进行分析。

(6)对内存快照进行分析

MAT分析内存快照的技巧：通常在内存溢出时分析内存快照也并没那么复杂，主要就是通过MAT来找到占据内存最大的对象。

一.首先发现占据内存最大的是大量的byte[]数组

大量的byte[]数组就占据了大约8G左右的内存空间，而当时线上机器给Tomcat的JVM堆内存分配的也就8G的内存而已。因此可以直接得出第一个结论：Tomcat工作线程在处理请求时会创建大量byte[]数组，大概有8G。大量的byte[]数组直接把JVM堆内存占满了，这就导致继续处理新请求时，没法继续在堆中分配新对象，从而OOM。如下图示：

二.接下来需要分析，到底是哪些byte[]数组

继续通过MAT深入查看，发现大概是类似下面的一大堆byte[]数组：

byte[10008192] @ 0x7aa800000 GET /order/v2 HTTP/1.0-forward... byte[10008192] @ 0x7aa800000 GET /order/v2 HTTP/1.0-forward... byte[10008192] @ 0x7aa800000 GET /order/v2 HTTP/1.0-forward... byte[10008192] @ 0x7aa800000 GET /order/v2 HTTP/1.0-forward...

上面只是写出来几个示例而已，其实当时看到了很多类似这样的数组，而且数组大小都是一致的10M。清点了一下，类似上面的数组大概就有800个，也就对应了8G的空间。

三.接着进一步思考，这种数组应该是谁创建的

可以在MAT上可以继续查看一下这个数组是被谁引用的，发现是由Tomcat的类引用的，具体来说是类似下面的这个类：

org.apache.tomcat.util.threads.TaskThread

这个类一看就是Tomcat自己的线程类，因此可以认为是Tomcat的线程创建了大量的byte[]数组，然后占据了8G内存。

此时我们发现Tomcat的工作线程大致有400个左右，即每个Tomcat工作线程会创建2个byte[]数组，每个byte[]数组是10M。也就是400个Tomcat工作线程在同时处理请求，创建了8G的byte[]数组，从而导致内存溢出。如下图示：

(7)系统每秒QPS才100

此时结合上图可知：一秒内来了400个请求，导致Tomcat的400个工作线程全部处理请求。每个工作线程在处理一个请求时，会创建2个数组，每个数组是10M，结果导致瞬间让8G的内存空间被占满了。

看起来根据MAT信息，分析出来的生产系统的情况就是如此。但是检查了一下系统的监控，发现每秒请求并不是400，而是100。

问题一：为何Tomcat的400个线程都处于工作状态

明明每秒才100个请求，为什么Tomcat的400个线程都处于工作状态？出现这种情况只有一种可能，那就是每个请求处理需要耗费4秒时间。如果每秒来100个请求，但是每个请求处理完毕需要4秒的时间。那么这会导致，在4秒内的某个瞬间就会有400个请求需要同时处理。从而也就会导致Tomcat的400个工作线程都在工作，出现上述情况。

问题二：为何Tomcat工作线程在处理一个请求时会创建2个10M的数组

这里可以到Tomcat的配置文件里搜索一下，发现了如下的一个配置：

max-http-header-size: 10000000

这个配置会导致Tomcat工作线程在处理请求时创建2个数组，每个数组的大小就是上面配置的10M。

因此可以总结一下系统运行时的场景了：每秒100个请求，每个请求处理需要4秒。导致4秒内的某个瞬间，400个请求会同时被400个线程处理。每个线程根据配置创建2个数组，每个数组10M，于是占满了8G的内存。如下图示：

(8)为什么处理一个请求需要4秒

这个问题绝对是偶发性的，不是每次处理请求都如此。因为这个系统的负责人说，平时处理一个请求也就几百毫秒而已。既然如此，那么唯一办法只能在日志里去找了，查看事故发生时的日志。发现日志中除了OOM外，还有大量的服务请求调用超时的异常，如下：

Timeout Exception...

也就是说，这个系统在通过RPC调用其他系统时出现大量的请求超时。马上翻看一下系统的RPC调用超时配置，惊讶地发现：这个系统的负责人将服务RPC调用超时时间设置了刚好是4秒。

也就是说，在这个时间里远程服务自己故障了，然后导致我们的系统RPC调用时访问不通。于是就会在配置好的4秒超时时间后抛出异常，在这4秒内，工作线程会直接卡死在无效的网络访问上。如下图示：

上图已经表述很清楚了：之所以每个请求要处理4秒，是因为下游服务故障了，网络请求失败了。此时会按设置好的4秒超时时间一直卡住4秒后才会抛出Timeout异常。然后请求才会处理结束，这就是一个请求处理需要4秒的根本原因。处理一个请求4秒会导致4秒内积压400请求同时在处理(每秒100请求)，最后导致400个工作线程创建800个10M的数组，耗尽8G内存而OOM。

(9)对系统进行优化

上述问题原因就是超时时间设置得太长了，因此将超时时间改为1秒。这样每秒100个请求，只有200个数组占据2G内存，不会占满堆内存。然后1秒内这100个请求会全部超时，请求就处理结束。下一秒再来100个请求又是新一轮处理，不会出现每秒积压100个请求，4秒内出现400个请求同时处理的情况。

另外，对Tomcat的参数，max-http-header-size可以适当调节小一些。这样Tomcat工作线程自身为请求创建的数组，不会占据太大的内存空间。

2.Jetty服务器的NIO机制如何导致堆外内存溢出(S区太小 + 禁NIO的显式GC)

(1)案例背景

(2)案例发生现场

(3)初步分析事故发生的原因

(4)解决OOM问题的技术储备建议

(5)堆外内存是如何申请的和如何释放的

(6)为什么会出现堆外内存溢出的情况

(7)真正的堆外内存溢出原因分析

(8)难道Java NIO就没考虑过这个问题吗

(9)最终对问题的优化

(1)案例背景

使用Jetty作为Web服务器时在某个罕见场景下发生的一次堆外内存溢出，这种场景其实并不多见，但可以学习这种场景的排查方法。

(2)案例发生现场

有一天突然收到线上的一个报警：某台机器部署的一个服务突然间就不可以访问了。此时第一反应当然是马上登录机器去看一下日志，因为服务挂掉，很可能是OOM导致的，当然也可能是其他原因导致的。这个时候在机器的日志中发现了如下的一些核心信息：

nio handle failed java.lang.OutOfMemoryError: Direct buffer memory at org.eclipse.jetty.io.nio.xxxx at org.eclipse.jetty.io.nio.xxxx at org.eclipse.jetty.io.nio.xxxx

上述日志告诉我们有OOM异常，但是是哪个区域导致的呢？居然是Direct buffer memory区域，且后面还有Jetty相关的方法调用栈。到此为止，根据这些日志基本就可以分析出这次OOM发生原因了。

(3)初步分析事故发生的原因

Direct buffer memory其实就是堆外内存，堆外内存是JVM堆内存外的一块内存空间，这块内存不是JVM管理的。Java代码在JVM堆之外使用的内存空间，就叫Direct buffer memory。

如果按英文字面理解，它的意思就是直接内存。所以从字面就可以看出，这块内存并不是JVM管理的，而是OS管理的。

Jetty可以理解为是一个和Tomcat一样的Web容器，它也是Java写的。写好的一个系统，可以打包后放入Jetty，然后启动Jetty即可。Jetty启动后本身就是一个JVM进程，它会监听一个端口号，比如9090。接着就可以向Jetty监听的9090端口发送请求，Jetty会把请求转交给我们用的Spring MVC之类的框架，而Spring MVC之类的框架再去调用我们写好的Controller之类的代码。

Jetty作为一个JVM进程运行我们写好的系统的流程，如下图示：

首先可以明确的是：这次OOM是Jetty这个Web服务器在使用堆外内存时导致的。所以基本可以推测出，Jetty服务器可能在不停地使用堆外内存。然后堆外内存空间不足，没法使用更多的堆外内存，此时就抛出OOM。如下图示：

(4)解决OOM问题的技术储备建议

Jetty是如何去JVM堆外申请一块堆外内存来使用的？然后这个堆外内存又是如何释放的？

这就涉及到Java的NIO底层技术细节，如果对NIO不了解，突然看到这个异常，估计是没法继续分析下去了。因此JVM性能优化相对还是较为容易，而且按照整个套路没太大难度。但如果要解决OOM问题，那么除了一些特别简单的模拟内存溢出，其他很多时候生产环境下的OOM问题，都是有技术难度的。

1000个工程师可能会遇到1000种不同的OOM问题，可能排查的思路是类似的，或者解决问题的思路是类似的。但是如果要解决各种OOM问题，那么需要对各种技术都有一定的了解。换句话说，需要有较为扎实的技术内功修为。

比如上面那个案例，就需要了解Tomcat的工作原理，才能分析清楚。同样这里的案例，也要求了解Java NIO技术的工作原理才能分析清楚。

所以需要对其他的核心主流技术做一些深层次的甚至源码级别的研究，这些底层技术积累会在线上系统出现问题时，帮助我们分析和解决问题。

(5)堆外内存是如何申请的和如何释放的

一.堆外内存是如何分配的

如果在Java代码申请使用一块堆外内存空间，要使用DirectByteBuffer。可通过这个类构建DirectByteBuffer对象，这个对象会在JVM堆内存里。构建该对象同时，会在堆外内存中划出一块内存空间与该对象关联起来。这就是分配堆外内存时的大致思路，如下图示：

二.堆外内存是如何释放的

当DirectByteBuffer对象没被引用成了垃圾对象后，自然会在某一次YGC或者FGC时把该DirectByteBuffer对象回收掉。只要回收一个DirectByteBuffer对象，就会释放掉其关联的堆外内存，如下图示：

(6)为什么会出现堆外内存溢出的情况

一般什么情况下会出现堆外内存的溢出？如果创建了很多DirectByteBuffer对象，那么就会占用大量的堆外内存。如果DirectByteBuffer对象没被GC线程回收，则堆外内存就不会释放。

久而久之，当堆外内存已经被大量的DirectByteBuffer对象关联使用后。如果要再创建DirectByteBuffer对象使用更多堆外内存，那么就会OOM。

什么情况会出现大量DirectByteBuffer对象存活，使堆外内存无法释放？有一种可能就是系统正在承载超高并发，负载压力很高。瞬时大量请求过来，创建过多的DirectByteBuffer占用了大量堆外内存。此时再继续想要使用堆外内存，就会内存溢出。但是这个系统是这种情况吗？明显不是。因为这个系统的负载其实没有那么高，也没有大量的瞬时请求过来。

(7)真正的堆外内存溢出原因分析

这时就得思路活跃起来了，我们完全可以去用jstat等工具观察一下线上系统的实际运行情况，同时根据日志看看一些请求的处理耗时，综合性地进行分析。当时我们通过jstat工具分析JVM运行情况，同时分析过往的GC日志。另外还看了系统各个接口的调用耗时后，分析出了如下结论。

一.首先看了接口的调用耗时

这个系统并发量不高，但是它每个请求处理较为耗时，平均每个请求需要一秒多的时间去处理。

二.然后通过jstat发现

随着系统不停地运行，会一直创建各种对象，包括Jetty本身会不停地创建DirectByteBuffer对象，直到新生代的Eden区满了，就会触发YGC。

但往往在进行YGC垃圾回收的一瞬间，可能有的请求还没处理完毕。此时就会有不少DirectByteBuffer对象处于存活状态，不能被回收掉。当然之前不少DirectByteBuffer对象对应的请求可能处理完毕了，它们就可以被回收。所以肯定会有一些DirectByteBuffer对象是处于存活状态的，那么这些存活状态下的对象就需要转入Survivor区域中。

但这个系统当时在上线时，内存分配不合理。年轻代只分配一两百M的空间，老年代反而给七八百M的空间，进而导致新生代中的Survivor区域只有10M左右的空间。而在YGC过后，一些存活下来的对象(包括DirectByteBuffer)会超过10M，于是这些存活的对象就没法放入Survivor中，只能直接进入老年代。

上述过程反复执行，慢慢就会导致一些DirectByteBuffer对象进老年代。老年代的DirectByteBuffer对象越来越多，而且都关联很多堆外内存。这些老年代里的DirectByteBuffer其实很多都是可以回收的了。但是因为老年代一直没塞满，所以没有触发FGC，自然也就不会回收老年代里的这些DirectByteBuffer对象。而老年代里这些没有被回收的DirectByteBuffer对象，却又一直与占据了大量的堆外内存空间关联着。

直到最后，当系统要继续使用堆外内存时：发现所有堆外内存都被老年代里大量的DirectByteBuffer对象给占用了。虽然它们可以被回收，但是无奈因为始终没有触发老年代的FGC。所以堆外内存也始终无法被回收掉，最后就导致堆外内存溢出问题。

(8)难道Java NIO就没考虑过这个问题吗

先不说如何解决这个问题，难道Java NIO就没考虑过会有上述问题吗？当然不是了，Java NIO是考虑到的。它知道可能会有很多DirectByteBuffer对象也许没被引用了，但是因为没有触发GC就导致它们一直占据着堆外内存。

所以在Java NIO的源码中会做如下处理：每次分配新的堆外内存发现不足时，都会调用System.gc()，以此提醒JVM执行一下GC去回收那些没被引用的DirectByteBuffer对象，从而释放堆外内存空间。

只要能触发垃圾回收去回收一些没被引用的DirectByteBuffer对象，那么就会释放一些堆外内存，自然就可分配更多对象到堆外内存去了。

可惜在JVM中设置了如下参数，该参数会导致System.gc()不生效，因此才导致上述情况。

-XX:+DisableExplicitGC

(9)最终对问题的优化

其实项目问题有两个：

一是内存设置不合理导致DirectByteBuffer对象进入老年代，导致堆外内存一直释放不掉。

二是设置了参数-XX:+DisableExplicitGC禁用了System.gc()，导致Java NIO没法显式触发去回收一些垃圾DIrectByteBuffer对象，导致堆外内存一直释放不掉。

因此需要做的事情就是：

一是合理分配内存，给年轻代更多内存，让Survivor区域有更大的空间。

二是放开参数-XX:+DisableExplicitGC这个限制，让System.gc()生效。

做完优化后，DirectByteBuffer对象一般就不会不断进入老年代了。只要它停留在年轻代，YGC后就会被正常回收，然后释放堆外内存。另外，只要放开对-XX:+DisableExplicitGC的限制。那么Java NIO发现堆外内存不足，就能通过System.gc()显式进行FGC。回收掉进入了老年代的一些DirectByteBuffer对象来释放一些堆外内存。

3.一次微服务架构下的RPC调用引发的OOM故障排查实践(MAT案例)

(1)案例背景

(2)系统架构介绍

(3)故障发生现场

(4)初步查找内存溢出的故障发生点

(5)分析内存快照找到占用内存最大的对象

(6)通过分析源代码找出原因

(7)一个关键点——RPC框架的类定义

(8)RPC框架的一个Bug——过大的默认值

(9)最终的解决方案

(1)解决系统OOM的核心能力

解决系统OOM故障的核心能力：必须对自己的线上系统，所使用的各种技术源码最好都要有深入理解，从服务框架到第三方框架、到Tomcat/Jetty等Web服务器、再到各种底层中间件系统。

因为一般线上系统OOM都不是简单地由我们写的代码导致的，往往都是因为系统使用了某个开源技术，该技术的内核代码有一定的故障和缺陷而导致的。这时要解决OOM问题，就必须深入到源码中去分析。

所以这里只能介绍各种真实的生产案例以及分析思路，真正到了具体的OOM故障时，由于每个系统的故障都是不同的。需要我们分析对应的技术底层，然后找到故障原因，最后解决故障。

(2)系统架构介绍

这个系统是比较早的一个系统，在进行服务间的RPC通信时，采用的是基于Thrift框架封装的RPC框架。然后公司的系统，就是基于这个RPC框架去进行通信。下图是一个最基本的服务间RPC调用的示例：

(3)故障发生现场

平时都是服务A通过RPC框架去调用服务B，但有一天服务A更新代码上线后发现没什么问题，但服务B却宕机了。明明修改代码和重新部署的是服务A，为什么造成服务B挂掉呢？如下图示：

登录到服务B的机器去查看服务B的日志，结果在里面发现了OOM异常，直接显示出堆内存溢出了；

java.lang.OutOfMemoryError Java heap space

可服务B为什么会OOM呢？难道是服务B的问题？那不如重启服务B？于是我们尝试重启了服务B。结果发现服务B重启过后很快又宕机了，而且原因还是OOM。这就奇怪了，因为服务A修改代码部署前，服务B从来没出现过这种情况。现在却是服务A修改了代码部署后才导致服务B出现了这种情况。

(4)初步查找内存溢出的故障发生点

一般内存溢出时，务必要先确认一下故障的发生点。这个通过查看日志就可以确认，因为在日志中都会有详细的异常栈信息。通过查看日志发现，引发OOM异常的，居然就是那个自研的RPC框架，当时的异常信息大概如下所示：

java.lang.OutOfMemoryError: Java heap space xx.xx.xx.rpc.xx.XXXClass.read() xx.xx.xx.rpc.xx.XXXClass.xxMethod() xx.xx.xx.rpc.xx.XXXClass.xxMethod()

由此可以初步确定，是自研的RPC框架在接收请求时引发了OOM，如下图示：

(5)分析内存快照找到占用内存最大的对象

既然已经定位到OOM故障发生的位置了，也就是谁引发的OOM。接下来用MAT分析一下发生OOM时，对内存占用最大的是哪个对象了。

打开OOM时的内存快照，发现占用内存最大的是一个超大的byte[]数组。当时一台机器给的堆内存也不过就是4G而已，而在内存快照中发现一个超大的byte[]数组，就已占据了差不多4G空间。

这个byte[]数组是哪儿来的？通过分析该byte[]数组的引用，会发现就是由RPC框架内部的类引用的。MAT里右击一个对象会出现一个菜单，里面有个选项就可以查看引用者。如下图示：

(6)通过分析源代码找出原因

一.整个分析流程步骤

第一步先定位到是谁导致的OOM

这时往往可能是由于某种技术，比如Tomcat、Jetty、或者是RPC框架。

第二步一般使用MAT等工具分析内存快照

找到当时占用内存最大的对象是谁，可以找找都是谁在引用这个对象，当然一般在第一步通过看日志的异常栈就大概知道导致OOM的类是谁。

第三步需要得对那个技术的源代码进行分析

比如对Tomcat、RPC框架源代码进行追踪分析。

一般分析到这一步，答案几乎快要揭晓了，通过代码分析找到故障发生原因。如果可能的话，最好在本地搭建类似的环境，把线上问题给复现出来，接下来就结合日志里的异常栈分析这个RPC框架的源代码。

二.这个RPC框架在接收请求时的流程

首先在服务A发送请求时，会对传输过来的对象进行序列化。这个序列化，就是把类似Request的对象变成一个byte[]数组。

然后对服务B而言，它首先会根据自定义的序列化协议，对发送过来的数据进行反序列化。接着把请求数据读取到一个byte[]缓存，然后调用业务代码处理请求。最后请求处理完毕，清理byte[]缓存。

以上便是这个RPC框架运行的原理了，接着需要在源码中要寻找一下：为什么用来缓冲请求的byte[]数组会达到几个G那么大？正常情况下，这个用来缓冲请求的byte[]数组应该最多不超过1M的。

(7)一个关键点——RPC框架的类定义

通过源码的分析，我们最终总算搞清楚了，原来当时有这么一个特殊的情况：因为RPC框架要进行对象传输，就必须让服务A和服务B都知道有该对象。举个例子，比如服务A要把一个Request对象传输给服务B。那么首先需要使用一种特定的语法定义一个对象文件，大概类似如下：

syntax = "proto3"; message Request {     string query = 1;     int32 page_number = 2;     int32 result_per_page = 3; }

然后会通过上面特殊语法写的文件可以反向生成一个对应的Java类，此时会生成一个Java语法的如下Request类：

public class Request {     //这里是一堆的自动生成的代码 }

接着这个Request类需要在服务A和服务B的工程里都要引入，这样服务A和服务B就知道：把Request交给服务A，它会自己进行序列化成字节流。然后到服务B时，它会把字节流反序列化成一个Request对象。如下图示：

服务A和服务B都必须知道有Request类的存在，才能把Request对象序列化成字节流，才能从字节流反序列化出一个Request类对象。

(8)RPC框架的一个Bug——过大的默认值

在上图中，服务B在接收到请求后，会先反序列化，接着把请求读出来放入一个byte[]数组。

但是这里RPC框架有一个Bug，就是一旦发现发送过来的字节流反序列化失败，就会开辟一个byte[]数组。这个byte[]数组默认4G，会把发送方的字节流原封不动地放进去。

而出现对字节流反序列化失败的原因是服务A修改了Request类，但服务B不知这次修改，Request是旧版本。比如服务A的Request类有15个字段，序列化成字节流发送给服务B了。但服务B的Request类只有10个字段，那么反序列化的时候就会失败。

所以最终的问题就出在这里了：当时服务A修改了很多Request类的字段，结果没告诉服务B。所以服务A上线后，服务B没能反序列化传过来的序列化的Request对象。此时服务B就会开辟一个默认4G的byte[]数组存放数据，然后导致OOM。如下图示：

(9)最终的解决方案

当时为什么要把异常情况下的数组默认大小设置为几个G那么大？这个其实也没办法，因为当时写这段代码的刚好是新手工程师。考虑反序列化失败，就原封不动封装字节流到数组，由对方自行处理。由于不知道字节流里有多少数据，所以就开辟一个大数组，保证能放下。且一般测试时又不会测到这种异常情况，所以之前一直没发现这个问题。

其实解决这个问题的办法很简单，把RPC框架中那个数组的默认值从4G调整为4M即可。一般请求都不会超过4M，不需要开辟那么大的数组，另外就是让服务A和服务B的Request类定义保持一致即可。

4.一次没有WHERE条件的SQL语句引发的OOM问题排查实践(使用MAT技巧)

(1)案例背景引入

(2)关于MAT工具对OOM故障的实践意义

(3)故障发生现场

(4)第一步检查内存中到底什么对象太多了

(5)第二步深入查看占用内存过多的对象

(6)生产案例的追踪

(7)第三步查找哪行代码创建了这么多对象

(8)继续对生产案例进行追踪

(1)案例背景引入

在使用Mybatis写SQL语句时，在某些情况下不加where条件也可执行，结果导致一下子查询出上百万条数据引发系统OOM。这个案例本身比较简单，不涉及太多其他的技术问题。下面通过这个案例来介绍使用MAT对线上内存快照进行分析的技巧。

(2)关于MAT工具对OOM故障的实践意义

如果系统触发OOM是由于Tomcat、Jetty、RPC框架之类的底层技术，那么MAT对这种系统来说用处并不是那么大。

因为最多就是用MAT找一找占用内存过多的对象，然后结合异常日志调用栈和MAT中的对象引用情况，初步定位是底层技术中的哪部分代码导致的内存溢出。

如果要真正解决这种内存溢出问题，还得去仔细研究Tomcat、Jetty、RPC框架之类技术的底层源码，然后结合线上系统的负载情况、访问压力、GC情况，以及底层技术的源码细节，才能分析清楚。

如果OOM是由于自己系统代码问题导致的，那么就容易解决得多了。只要根据MAT层层分析，就可以定位到代码的问题所在。毕竟自己写的代码自己是最熟悉的，所以很快就可以解决问题。

(3)故障发生现场

某天突然收到反馈说线上一个系统崩溃不可用了，此时立即登录到线上机器去查看日志。在日志中果然发现了OOM的异常，堆内存溢出了：

java.lang.OutOfMemoryError，java heap space

那么下一步就是把自动导出的内存快照拷贝到电脑上，用MAT去分析。下面介绍如何巧妙的用MAT工具迅速定位问题代码。

(4)第一步检查内存中到底什么对象太多了

这时可以用MAT中的Histogram功能去检查占用内存最多的对象有哪些。当然MAT的那个内存泄漏报告的使用，那个功能也是没问题也很好用。但这里介绍另外一套分析思路，其实原理都是类似的。

分析内存快照，就是要找到占用内存最大的对象。然后找到谁在引用这个对象，是哪个线程在引用。接着找到创建这些对象的相关代码和方法，这样就可以到对应的源码里去分析问题了。

在如下图中，红圈处那个按钮就是Histogram按钮，点击过后就会进入另外一个界面。

接着进入Histogram界面，如下图示：

在这个界面中，就可以看到是谁占用过多内存了。比如这里明显是Demo1$Data这个内部类占用了过多内存，而且这里显示Demo1$Data对象有10000个，此时我们就会想看看这些Demo1$Data对象都是什么？

(5)第二步深入查看占用内存过多的对象

为了查看这些Demo1$Data对象都会是什么？此时进入第二步，即查看占用内存过多的对象是被谁引用、哪个线程引用、里面都是什么。也就是按照下图，点击红圈处的按钮：

点击上图那个红圈处的按钮之后，就会进入一个dominator_tree的界面，dominator_tree界面会展示出当前JVM中所有的线程。如下图示：

在dominator_tree界面可以清晰看到哪些线程创建了过多的对象，比如排第一的线程是：java.lang.Thread @ 0x5c0020838 main Thread。这就表明了是一个main线程创建了过多的对象，那接下来就可以直接展开这个线程，看看它到底创建了哪些对象。如下图示：

当展开main Thread后，发现有一个java.util.ArrayList @ 0x5c00206a8，说明main线程创建了一个巨大的ArrayList。于是继续展开这个ArrayList，发现里面是一个java.lang.Object[]数组。于是继续展开，就会看到大量的Demo1$Data对象了。至此真相大白。

其实在dominator_tree界面就能很快找到是哪个线程创建了过多的对象，而且通过层层展开，可以看到这个线程创建了哪些对象太多了，这样就和之前的Histogram界面中占用内存最多的Demo1$Data对上了，而且这里可以轻易看到每个Demo1$Data对象的详细的情况。

(6)生产案例的追踪

当时对于那个线上生产案例而言，追踪到dominator_tree界面这里，发现某个Tomcat的工作线程创建了一大堆的java.lang.HashMap。那么这些java.lang.HashMap中是什么呢？

我们发现全都是各种从数据库里查出来的字段，因为只要展开那个HashMap就能看到查出来放入内存的所有数据。

所以看到这一步基本就很明确了：就是工作线程处理一个请求时，发起了一个SQL查询，查出大量的数据。每条数据是一个HashMap，就是这大量的数据导致了系统的OOM。

(7)第三步查找哪行代码创建了这么多对象

找到占用内存最大的对象后，最后一步就是要定位是哪一行代码或者是哪个方法创建了那么多对象。这时又需要另外一个视图了，如下图的红圈处所示：

点击上图红圈的按钮会进入一个thread_overview界面，下图展示出JVM中所有的线程以及每个线程当时的方法调用栈，以及每个方法创建了哪些对象。

从上图可直接看到一个main Thread，它先执行了一个Demo1.java类中的第12行处的一个Demo1.main()方法，接着main方法又执行了一个java.lang.Thread类的sleep()方法。任何一个线程在此时此刻执行和调用了哪些方法，都会在这里显示出来。

我们接着展开上图中的Demo1.main()方法，就可以看到线程调用每个方法的时候创建和引用了哪些对象。如下图示：

在上图中，我们发现Demo1.main方法执行的时候创建了一个ArrayList，展开发现是一个java.lang.Object[]数组，再次展开发现就是一大堆的Demo1$Data对象。到此真相大白，一清二楚。

通过上述步骤，我们就可以快速的定位出来占用内存过多的对象，以及是哪个线程创建了这些对象，线程执行哪个方法时创建了这些对象，每个对象的细节我们都可以看得清清楚楚。

(8)继续对生产案例进行追踪

采用上述方法，对生产案例进行追踪，定位到系统中的一个业务方法。该方法在执行查询操作时，因没带WHERE条件，查询出上百万数据，最后导致内存溢出。因此对那个方法对应的SQL语句进行修改即可。

MAT使用技巧总结：

一.首先通过Histogram界面找占用大的对象

二.然后进入dominator_tree界面找对应的线程

三.接着进入thread_overview界面找线程对应的方法调用栈

5.每天10亿数据的日志分析系统的OOM问题排查(堆内存太小 + 递归要谨慎)

(1)案例背景

(2)事故发生现场

(3)初步分析内存快照

(4)问题在JVM参数上

(5)分析一下JVM的GC日志

(6)分析一下JVM运行时内存使用模型

(7)优化第一步：增加堆内存大小

(8)优化第二步：改写代码

(1)案例背景

这个案例背景是一个每天10亿数据量的日志清洗系统，这个系统做的事情非常简单，主要是从Kafka中不停消费各种日志数据，然后对日志的格式进行清洗。比如对一些涉及到用户敏感信息的字段(姓名、手机号)进行脱敏处理，然后把清洗后的数据交付给其他的系统去使用，比如推荐系统、广告系统、分析系统都会去使用这些清洗好的数据。如下图示：

(2)事故发生现场

某天突然收到线上的报警，发现日志清洗系统发生了OOM异常，登陆到线上机器查看日志后，发现还是那么经典的堆内存溢出问题。

java.lang.OutOfMemoryError: java heap space

于是便来分析一下问题到底出在哪里了。首先看异常日志，定位一下到底是谁导致的这个问题，当时我们在日志里大致看到了类似如下的一些信息：

java.lang.OutOfMemoryError: java heap space xx.xx.xx.log.clean.XXClass.process() xx.xx.xx.log.clean.XXClass.xx() xx.xx.xx.log.clean.XXClass.xx() xx.xx.xx.log.clean.XXClass.process() xx.xx.xx.log.clean.XXClass.xx() xx.xx.xx.log.clean.XXClass.xx() xx.xx.xx.log.clean.XXClass.process() xx.xx.xx.log.clean.XXClass.xx() xx.xx.xx.log.clean.XXClass.xx()

从日志中可以很明显发现：同样的一个方法(XXClass.process())反复出现了多次，最终导致OOM。

这时通过日志，有经验的可能已经可以发现一个问题了。那就是在某一处代码出现了大量的递归操作，正是大量的递归操作，反复调用一个方法后，导致了堆内存溢出问题。

初步定位是XXClass.process()方法出现了递归操作导致OOM，接下来用MAT分析一下内存快照。

(3)初步分析内存快照

接着开始分析生产现场的内存快照，在分析MAT时发现了一个问题：因为有大量的XXClass.process()方法递归执行，每个XXClass.process()方法中都创建了大量的char数组，最后因为XXClass.process()方法又多次递归调用，也就导致了大量的char[]数组耗尽了内存。如下图示，每次调用都创建大量char[]数组导致内存溢出。

(4)问题在JVM参数上

基本定位出问题所在了，但当时还发现了另一个比较大的问题。虽然XXClass.process()方法递归调用了多次，但实际上在MAT中发现递归调用的次数也并不多，大概就几十次递归，而且所有递归调用加起来创建的char[]数组对象总和也就最多1G而已。

如果是这样的话，其实我们应该先注意一个问题，那就是可能这次OOM的发生不一定是代码写得有多差。可能就是JVM的内存参数设置的不对，给堆内存分配的空间太小了。

(5)分析一下JVM的GC日志

为了确认堆内存到底是不是设置太小了，就得分析发生GC的具体过程。现在系统已经宕机，我们唯一可以看到JVM启动参数的，就是GC日志。从GC日志中，可以看到JVM启动时的完整参数设置的，核心的内容如下：

 -Xmx1024m -Xms1024m   -XX:+PrintGCDetails -XX:+PrintGC()   -XX:+HeapDumpOnOutOfMemoryError -Xloggc:/opt/logs/gc.log -XX:HeapDumpPath=/opt/logs/dump

这里的参数主要是把GC日志详细记录在了一个日志文件里。另外指定了内存溢出时要导出内存快照，还有就是堆内存给1G，但是这台机器可是4核8G的。

接着我们看一下当时记录下来的gc.log日志：

[Full GC (Allocation Failure)  866M->654M(1024M)] [Full GC (Allocation Failure)  843M->633M(1024M)] [Full GC (Allocation Failure)  855M->621M(1024M)] [Full GC (Allocation Failure)  878M->612M(1024M)]

上面把GC日志中大量无关的信息省略掉了，因为和我们分析关系不大。从上面的GC日志可以发现：Allocation Failure触发的FGC很多，每次FGC都只能回收一点点对象。另外日志里显示的是每秒都会执行一次FGC，这就很可怕了。

所以基本上可以明确GC的具体过程如下：

一.XXClass.process()方法递归创建大量char[]数组，导致堆内存满了。

二.然后导致连续一段时间，每秒触发一次FGC。因为内存都满了，特别是老年代几乎都满了。所以可能是每秒执行YGC前，发现老年代可用空间不足，提前触发FGC。也可能是YGC存活对象太多无法放入S区，老年代又放不下，只能FGC。

三.每次FGC只能回收少量对象，直到某一次FGC回收不到任何对象。然后新的对象无法放入堆内存，此时就会触发内存溢出的异常，如下图示：

因此堆内存肯定是偏小了，从而导致频繁的FGC。

(6)分析一下JVM运行时内存使用模型

接着我们用jstat分析一下当时JVM运行时的内存模型。当时重启了系统，每秒打印一次jstat的统计信息，就看到了下面的情况：

S0 S1  E O YGC FGC 0 100 57 69 36 0 0 100 57 69 36 0 0 100 65 69 37 0 0 100 0  99 37 0 0 100 0  87 37 1

一.刚开始都是新生代的Eden区在涨。

二.接着YGC从36到37，就发生了一次YGC。

三.然后Old区从占比69%到99%，说明YGC后存活对象太多，Survivor区放不下，直接进老年代了。

四.接着老年代都占了99%了，直接就触发了一次FGC。但这次FGC仅让老年代从占比99%降到87%而已，回收了少量的对象。

五.上面的那个过程反复循环几次，新生代的对象反复进入老年代，不停触发FGC，但回收不了多少对象。几次循环过后，老年代满了，可能FGC没回收多少对象。新的对象又放不下，就触发OOM了。

(7)优化第一步：增加堆内存大小

所以这个OOM的问题，就是内存分配不足的问题。因此第一步，给堆内存加大空间，给堆内存5G的空间(4核8G机器)。接着运行系统，通过jstat观察，就可以发现：每次YGC过后存活对象都落入S区了，不会随便进入老年代，而且因为堆内存很大，基本上运行一段时间不会发生OOM问题了。

(8)优化第二步：改写代码

另外就是改写代码，让它不要占用过多的内存。代码之所以递归，就是因为在一条日志中，可能会出现很多用户的信息。一条日志也许会合并包含了十几个到几十个用户的信息，这时代码中就会递归十几次到几十次去处理这个日志。每次递归都会产生大量的char[]数组，这些数组是来自切割了的日志，用来后续处理的。

其实这个代码写的完全没有必要，因为对每一条日志，如果发现包含了多个用户的信息。其实就对这一条日志切割出来进行处理即可，完全没有必要递归调用。每次调用都切割一次日志，生成大量的char[]数组。这一步代码优化后，便发现线上系统的内存使用情况降低了10倍以上。

所以JVM有风险，递归要谨慎。

6.类加载器过多引发OOM问题排查(服务假死自己恢复+ top判断 + OS杀进程)

(1)案例背景

(2)使用top命令检查机器资源使用

(3)当内存使用这么高时会发生什么

(4)到底是谁占用了过多的内存

(1)案例背景

公司里有一个非常正常的线上的服务，采用的是Web系统部署在Tomcat的方式来启动的。但是有一段时间，经常会收到反馈说这个服务非常不稳定，访问这个服务的接口会出现假死问题。也就是一段时间内无法访问这个服务的接口，但过一会又可以访问了。

(2)使用top命令检查机器资源使用

因为当时的情况是服务假死，接口无法调用，并不是OOM之类的异常。所以此时也很难直接去看它的线上日志，根据日志马上进行问题定位。

因此针对服务假死这个问题：首先可以用top命令去检查一下机器的资源使用量，通过top命令查看机器上运行的各进程对CPU和内存两种资源的使用量。

一.接口假死的两者情况

为什么要先用top看机器资源？因为如果服务出现无法调用接口假死的情况，首先要考虑的是两种原因。

第一种原因：这个服务可能使用了大量的内存，内存始终无法释放，导致频繁FGC。也许每秒都执行一次FGC，结果每次都回收不了，最终导致频繁FGC。频繁FGC又会频繁Stop the World，所以接口调用时就会出现频繁假死。

第二种原因：可能是这台机器的CPU负载太高了，也许是某个进程耗尽了CPU资源。CPU资源耗尽会导致这个服务的线程始终无法得到CPU资源去执行。没有CPU资源去执行也就无法响应接口调用请求，从而频繁假死。

因此针对服务假死的问题，先通过top命令查看，就知道关键点了。

二.根据JVM进程对CPU消耗和内存的消耗判断是否发生频繁GC

针对线上这台机器使用top命令检查之后，就发现了一个问题：这个服务的进程对CPU耗费很少，仅仅耗费了1%的CPU资源。但是这个进程虽然耗费1%CPU，却耗费了50%以上的内存资源，这个就引起了我们的注意。

因为这台机器是4核8G的标准线上虚拟机，针对这种机器通常会给部署的服务的JVM分配5~6G总内存。除掉Metaspace区，堆内存大概会给到4G~5G，毕竟还得给创建大量的线程留下一部分内存。

由于JVM使用的内存主要是三类：栈内存、堆内存和Metaspace区域，现在给Metaspace区域512M以上的空间、堆内存可能有4G。每个线程的栈内存给1M，JVM进程有几百上千线程，也要将近1G内存。

此时JVM服务进程对内存耗费已超过50%，说明它几乎快把分配给它的内存消耗尽。而且最关键的是，它长期保持对内存资源的消耗在50%以上甚至更高，这说明JVM在GC时并没有把内存回收掉。

(3)当内存使用过高时会发生什么

一.JVM进程对内存使用率过高的可能原因

既然这个服务的进程对内存使用率这么高，可能发生的问题也就三种：

第一种是内存使用率居高不下，导致频繁FGC

第二种是内存使用过多，导致OOM内存溢出

第三种是内存使用率过高，导致JVM进程被OS杀掉

二.分析这是属于哪种原因导致内存使用率过高

首先分析第一种情况，于是使用jstat分析一下JVM运行的情况。发现内存使用率确实很高，也确实经常发生GC。但实际上GC耗时每次也就几百毫秒，并没有耗费过多的时间。也就是说虽然GC频率高，但是其实是个常规现象。而且这个服务虽然经常频繁GC，但也没听见上游服务反馈说服务假死。因此第一种情况可以直接排除掉了。

接着分析第二种情况，难道是JVM自己有时候发生OOM挂掉了？挂掉时必然导致服务无法访问，上游服务肯定会反馈说我们服务死掉的。但是检查应用服务自身日志，并没有看到任何日志输出OOM异常。

接着分析第三种情况，也就是JVM运行时要申请的内存过多。结果内存不足，有时OS会直接杀掉这个进程。可能在进程被杀掉的过程中，就出现了上游服务无法访问的情况。而该机器上的JVM进程是有监控脚本的：一旦JVM进程被杀掉，会有脚本自动把JVM进程重新启动拉起来。所以也许其他服务过一会就会发现，服务又可以访问了。

(4)到底是谁占用了过多的内存

如果要解决这个问题，就必须要找出到底是什么对象占用内存过多，进而申请过多的内存，最后导致进程被杀掉了。很简单，直接从线上导出一份内存快照即可。我们在线上系统运行一段时间后，用top命令和jstat命令观察一段时间，发现当JVM已耗费超50%内存时，迅速导出一份内存快照进行分析。

此时用MAT进行内存快照分析时发现，存在一大堆的ClassLoader也就是类加载器，大概有几千个。而且这些类加载器加载的东西，都是大量的byte[]数组，这些一共占用了超过50%的内存。

那么这些ClassLoader是哪儿来的？为什么会加载那么多的byte[]数组？其实除了可以用类加载器加载类，还可以用类加载器加载一些其他资源。比如可以用类加载器加载一些外部配置文件。

当时写这个系统代码的工程师做了自定义类加载器，而且在代码里没限制地创建大量自定义类加载器，重复加载大量数据。结果经常一下子就把内存耗尽了，进程就被杀掉了。

因此解决这个问题非常的简单，直接就是修改代码，避免重复创建几千个自定义类加载器，避免重复加载大量数据到内存。

7.数据同步系统频繁OOM内存溢出的排查(时不时OOM+内存泄露+MAT排查)

(1)案例背景

(2)堆内存OOM的三种原因

(3)通过jstat来确认我们的推断

(4)通过MAT找到占用内存最大的对象

(1)案例背景

首先说一下案例背景：线上有一个数据同步系统，是专门负责去同步另外一个系统的数据，另外一个系统会不停地发布自己的数据到Kafka中，然后该数据同步系统从Kafka里消费数据，接着保存到自己的数据库中。大概的流程如下图示：

结果就这么一个简单的系统，居然时不时就报一个内存溢出的错误。然后就得重启系统，过了一段时间又会再次内存溢出一下。而且当这个系统处理的数据量越来越大，它内存溢出的频率越来越高。到这种情况，就必须要处理一下了。

(2)堆内存OOM的三种原因

既然每次重启后过一段时间会出现内存溢出的问题，那么就说明每次重启后，内存都会不断上涨。

JVM出现内存溢出，通常有三种原因：

原因一是并发太高，大量并发创建过多的对象，导致系统直接崩溃了

原因二是内存泄漏，有很多对象都在内存里，无论如何GC都回收不掉

原因三是代码问题，导致某种情况下加载了大量数据，创建大量对象

那么这个场景是怎么回事呢？这个系统的负载并不高，虽然数据量不少，但并不是瞬时高并发场景。这么看来，很可能是随着时间推移，某种对象越来越多，都在内存里了。然后不断地触发GC，结果每次GC都回收不掉这些对象。一直到最后，内存实在不足了，就会内存溢出。如下图示：

(3)通过jstat来确认我们的推断

接着直接在一次重启系统后，用jstat观察JVM运行的情况。我们发现，老年代的对象一直在增长，不停在增长。每次YGC过后，老年代的对象就会增长不少。而且当老年代的使用率达到100%后，会正常触发FGC。但是FGC根本回收不掉任何对象，导致老年代使用率还是100%。然后老年代使用率维持100%一段时间过后，就会报内存溢出的问题。因为此时再有新的对象进入老年代，实在没有空间存放它了。

所以这就基本确认了我们的判断：每次系统启动，不知道什么对象会一直进入堆内存。而且随着YGC执行，对象会一直进入老年代。最后触发FGC都无法回收老年代的对象，最终就是内存溢出。

(4)通过MAT找到占用内存最大的对象

在内存快照中，发现有一个队列数据结构，直接引用了大量的数据，正是这个队列数据结构占满了内存。

那这个队列是干什么用的？从Kafka取出的数据会先写入这个队列，接着再从这个队列写入数据库。由于要额外做一些中间的数据处理和转换，所以才在中间加一个队列。如下图示：