JVM 实战—OOM 的生产案例
1.每秒仅上百请求的系统为何会 OOM(RPC 超时时间设置过长导致 QPS 翻几倍)
(1)案例背景
在这个案例中,一个每秒仅仅只有 100+请求的系统却因频繁 OOM 而崩溃。这个 OOM 问题会涉及:Tomcat 底层工作原理、Tomcat 内核参数的设置、服务请求超时时间。
(2)系统发生 OOM 的生产现场
某一天突然收到线上系统的一个报警,说系统发生了异常。一看异常信息让人大惊失色,居然是 OOM 问题。这个问题不得了,因为一旦 JVM 发生 OOM,将会导致系统直接崩溃。OOM 代表的是 JVM 本身已经没办法继续运行了。因此马上登录到系统的线上机器去查看对应的日志。
需要注意:一旦收到系统 OOM 报警,或者有人突然反馈说线上系统崩溃了。第一件事情一定是登录到线上机器去看日志,而不是做别的事情。当时在机器的日志文件中看到类似下面的一句话:
根据 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)异常日志
接着查看当时线上系统的日志,发现如下异常:
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[]数组:
上面只是写出来几个示例而已,其实当时看到了很多类似这样的数组,而且数组大小都是一致的 10M。清点了一下,类似上面的数组大概就有 800 个,也就对应了 8G 的空间。
三.接着进一步思考,这种数组应该是谁创建的
可以在 MAT 上可以继续查看一下这个数组是被谁引用的,发现是由 Tomcat 的类引用的,具体来说是类似下面的这个类:
这个类一看就是 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 的配置文件里搜索一下,发现了如下的一个配置:
这个配置会导致 Tomcat 工作线程在处理请求时创建 2 个数组,每个数组的大小就是上面配置的 10M。
因此可以总结一下系统运行时的场景了:每秒 100 个请求,每个请求处理需要 4 秒。导致 4 秒内的某个瞬间,400 个请求会同时被 400 个线程处理。每个线程根据配置创建 2 个数组,每个数组 10M,于是占满了 8G 的内存。如下图示:
(8)为什么处理一个请求需要 4 秒
这个问题绝对是偶发性的,不是每次处理请求都如此。因为这个系统的负责人说,平时处理一个请求也就几百毫秒而已。既然如此,那么唯一办法只能在日志里去找了,查看事故发生时的日志。发现日志中除了 OOM 外,还有大量的服务请求调用超时的异常,如下:
也就是说,这个系统在通过 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)案例背景
使用 Jetty 作为 Web 服务器时在某个罕见场景下发生的一次堆外内存溢出,这种场景其实并不多见,但可以学习这种场景的排查方法。
(2)案例发生现场
有一天突然收到线上的一个报警:某台机器部署的一个服务突然间就不可以访问了。此时第一反应当然是马上登录机器去看一下日志,因为服务挂掉,很可能是 OOM 导致的,当然也可能是其他原因导致的。这个时候在机器的日志中发现了如下的一些核心信息:
上述日志告诉我们有 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()不生效,因此才导致上述情况。
(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)解决系统 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 异常,直接显示出堆内存溢出了;
可服务 B 为什么会 OOM 呢?难道是服务 B 的问题?那不如重启服务 B?于是我们尝试重启了服务 B。结果发现服务 B 重启过后很快又宕机了,而且原因还是 OOM。这就奇怪了,因为服务 A 修改代码部署前,服务 B 从来没出现过这种情况。现在却是服务 A 修改了代码部署后才导致服务 B 出现了这种情况。
(4)初步查找内存溢出的故障发生点
一般内存溢出时,务必要先确认一下故障的发生点。这个通过查看日志就可以确认,因为在日志中都会有详细的异常栈信息。通过查看日志发现,引发 OOM 异常的,居然就是那个自研的 RPC 框架,当时的异常信息大概如下所示:
由此可以初步确定,是自研的 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。那么首先需要使用一种特定的语法定义一个对象文件,大概类似如下:
然后会通过上面特殊语法写的文件可以反向生成一个对应的 Java 类,此时会生成一个 Java 语法的如下 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)案例背景引入
在使用 Mybatis 写 SQL 语句时,在某些情况下不加 where 条件也可执行,结果导致一下子查询出上百万条数据引发系统 OOM。这个案例本身比较简单,不涉及太多其他的技术问题。下面通过这个案例来介绍使用 MAT 对线上内存快照进行分析的技巧。
(2)关于 MAT 工具对 OOM 故障的实践意义
如果系统触发 OOM 是由于 Tomcat、Jetty、RPC 框架之类的底层技术,那么 MAT 对这种系统来说用处并不是那么大。
因为最多就是用 MAT 找一找占用内存过多的对象,然后结合异常日志调用栈和 MAT 中的对象引用情况,初步定位是底层技术中的哪部分代码导致的内存溢出。
如果要真正解决这种内存溢出问题,还得去仔细研究 Tomcat、Jetty、RPC 框架之类技术的底层源码,然后结合线上系统的负载情况、访问压力、GC 情况,以及底层技术的源码细节,才能分析清楚。
如果 OOM 是由于自己系统代码问题导致的,那么就容易解决得多了。只要根据 MAT 层层分析,就可以定位到代码的问题所在。毕竟自己写的代码自己是最熟悉的,所以很快就可以解决问题。
(3)故障发生现场
某天突然收到反馈说线上一个系统崩溃不可用了,此时立即登录到线上机器去查看日志。在日志中果然发现了 OOM 的异常,堆内存溢出了:
那么下一步就是把自动导出的内存快照拷贝到电脑上,用 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)案例背景
这个案例背景是一个每天 10 亿数据量的日志清洗系统,这个系统做的事情非常简单,主要是从 Kafka 中不停消费各种日志数据,然后对日志的格式进行清洗。比如对一些涉及到用户敏感信息的字段(姓名、手机号)进行脱敏处理,然后把清洗后的数据交付给其他的系统去使用,比如推荐系统、广告系统、分析系统都会去使用这些清洗好的数据。如下图示:
(2)事故发生现场
某天突然收到线上的报警,发现日志清洗系统发生了 OOM 异常,登陆到线上机器查看日志后,发现还是那么经典的堆内存溢出问题。
于是便来分析一下问题到底出在哪里了。首先看异常日志,定位一下到底是谁导致的这个问题,当时我们在日志里大致看到了类似如下的一些信息:
从日志中可以很明显发现:同样的一个方法(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 启动时的完整参数设置的,核心的内容如下:
这里的参数主要是把 GC 日志详细记录在了一个日志文件里。另外指定了内存溢出时要导出内存快照,还有就是堆内存给 1G,但是这台机器可是 4 核 8G 的。
接着我们看一下当时记录下来的 gc.log 日志:
上面把 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 的统计信息,就看到了下面的情况:
一.刚开始都是新生代的 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)案例背景
公司里有一个非常正常的线上的服务,采用的是 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)案例背景
首先说一下案例背景:线上有一个数据同步系统,是专门负责去同步另外一个系统的数据,另外一个系统会不停地发布自己的数据到 Kafka 中,然后该数据同步系统从 Kafka 里消费数据,接着保存到自己的数据库中。大概的流程如下图示:
结果就这么一个简单的系统,居然时不时就报一个内存溢出的错误。然后就得重启系统,过了一段时间又会再次内存溢出一下。而且当这个系统处理的数据量越来越大,它内存溢出的频率越来越高。到这种情况,就必须要处理一下了。
(2)堆内存 OOM 的三种原因
既然每次重启后过一段时间会出现内存溢出的问题,那么就说明每次重启后,内存都会不断上涨。
JVM 出现内存溢出,通常有三种原因:
原因一是并发太高,大量并发创建过多的对象,导致系统直接崩溃了
原因二是内存泄漏,有很多对象都在内存里,无论如何 GC 都回收不掉
原因三是代码问题,导致某种情况下加载了大量数据,创建大量对象
那么这个场景是怎么回事呢?这个系统的负载并不高,虽然数据量不少,但并不是瞬时高并发场景。这么看来,很可能是随着时间推移,某种对象越来越多,都在内存里了。然后不断地触发 GC,结果每次 GC 都回收不掉这些对象。一直到最后,内存实在不足了,就会内存溢出。如下图示:
(3)通过 jstat 来确认我们的推断
接着直接在一次重启系统后,用 jstat 观察 JVM 运行的情况。我们发现,老年代的对象一直在增长,不停在增长。每次 YGC 过后,老年代的对象就会增长不少。而且当老年代的使用率达到 100%后,会正常触发 FGC。但是 FGC 根本回收不掉任何对象,导致老年代使用率还是 100%。然后老年代使用率维持 100%一段时间过后,就会报内存溢出的问题。因为此时再有新的对象进入老年代,实在没有空间存放它了。
所以这就基本确认了我们的判断:每次系统启动,不知道什么对象会一直进入堆内存。而且随着 YGC 执行,对象会一直进入老年代。最后触发 FGC 都无法回收老年代的对象,最终就是内存溢出。
(4)通过 MAT 找到占用内存最大的对象
在内存快照中,发现有一个队列数据结构,直接引用了大量的数据,正是这个队列数据结构占满了内存。
那这个队列是干什么用的?从 Kafka 取出的数据会先写入这个队列,接着再从这个队列写入数据库。由于要额外做一些中间的数据处理和转换,所以才在中间加一个队列。如下图示:
那么问题就出在这个队列是怎么用的,由于从 Kafka 消费数据是可以一下子消费一批的(比如几百条数据)。所以当时直接把每次消费的一批数据做成一个 List,然后放入队列中。最后就造成了如下这种情况,这个队列有大量元素,每个元素都是一个 List,每个 List 有几百条数据。
所以这种做法一定会导致内存中的队列积压大量数据,最终就会 OOM。而且只要数据还停留在队列中,就没有办法被回收。如下图示:
这就是一个典型的对生产和消费的速率没控制好的案例:从 Kafka 里消费出数据放入队列的速度很快。但从队列里消费数据进行处理,然后写入存储的速度较慢。最终导致内存队列快速积压数据,导致内存溢出,而且这种让队列里的每个元素都是一个 List 的做法,也会导致内存队列能容纳的数据量大幅膨胀。
最终的解决方法很简单:把上述内存队列的使用修改一下,做成定长的阻塞队列即可。然后每次从 Kafka 消费出数据,直接将数据写入队列,而不是 List。
比如队列中最多 1024 个元素,那么内存中最多就是 1024 个数据,如下图示:
一旦内存队列满了,Kafka 消费线程就会停止工作,因为被队列阻塞住了,就不会让内存队列中的数据过多。
8.线上系统的 JVM 参数优化、GC 问题定位排查、OOM 分析解决总结
(1)JVM 运行系统时的工作原理
一.内存各个部分的划分
二.代码执行过程中各内存区域如何配合工作
三.对象是如何分配的
四.GC 如何触发
五.GC 执行的原理是什么
六.常见的用于控制 JVM 的一些核心参数
(2)JVM 参数在上线前如何预设、测试时如何调整、上线后如何优化
对于一个开发好的系统:首先应该如何通过预估的方法给它设置一些相对合理的 JVM 参数,然后在测试时如何合理的优化调整 JVM 参数,接着在线上运行时如何对 JVM 进行监控,如何对线上出现 GC 性能问题时进行合理优化。
(3)如何分析定位解决线上 OOM 问题
出现 OOM 的三种原因,三种 OOM 的定位和解决方法,OOM 的一些生产案例。
文章转载自:东阳马生架构
评论