网站设计 线框图,广州市学校安全教育平台官网,单位网站建设工作总结,大气宽屏网站模板企业源码带后台大纲
1.每秒仅上百请求的系统为何会OOM(RPC超时时间设置过长导致QPS翻几倍)
2.Jetty服务器的NIO机制如何导致堆外内存溢出(S区太小 禁NIO的显式GC)
3.一次微服务架构下的RPC调用引发的OOM故障排查实践(MAT案例)
4.一次没有WHERE条件的SQL语句引发的OOM问题排查实践(使用MA…大纲
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 memoryat org.eclipse.jetty.io.nio.xxxxat org.eclipse.jetty.io.nio.xxxxat 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 spacexx.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.OutOfMemoryErrorjava 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 spacexx.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 FGC0 100 57 69 36 00 100 57 69 36 00 100 65 69 37 00 100 0 99 37 00 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。每个线程的栈内存给1MJVM进程有几百上千线程也要将近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取出的数据会先写入这个队列接着再从这个队列写入数据库。由于要额外做一些中间的数据处理和转换所以才在中间加一个队列。如下图示 那么问题就出在这个队列是怎么用的由于从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的一些生产案例。
