案例实战:每秒10万并发的BI系统,如何定位和解决频繁Young GC问题?
服务于百万级商家的BI系统是什么
先说一下我们线上一个真实的生产系统,是一个服务于百万级商家的BI系统。所谓BI系统,很多开发业务系统的同学可能没接触过,简单介绍一下他的背景。
简单来说,比如一个平台有数十万甚至上百万的商家在你的平台上做生意,会使用你的这个平台系统,此时一定会产生大量的数据
然后基于这些数据我们需要为商家提供一些数据报表,比如:每个商家每天有多少访客?有多少交易?付费转化率是多少?当然实际情况会比这个简单几句话复杂很多,我们这里就简单说个概念而已。
所以此时就需要一套BI系统,所谓BI,英文全称是“Business Intelligence”,也就是“商业智能”。其实也别想的太高大上了,说白了,就是把一些商家平时日常经营的数据收集起来进行分析,然后把各种数据报表展示给商家的一套系统。所谓“商业智能”,指的就是给你看一些数据报表,然后让你平时能够更好的了解自己的经营状况,然后让老板“智能”的去调整经营策略,提升业绩。
所以类似这样的一个BI系统,大致的运行逻辑如下所示,首先从我们提供给商家日常使用的一个平台上会采集出来很多商家日常经营的数据,如下图所示。
接着就可以对这些经营数据依托各种大数据计算平台,比如Hadoop、Spark、Flink等技术进行海量数据的计算,计算出来各种各样的数据报表,如下图所示。
然后我们需要将计算好的各种数据分析报表都放入一些存储中,比如说MySQL、Elastcisearch、HBase都可以存放类似的数据,如下图所示。
最后一步,就是基于MySQL、HBase、Elasticsearch中存储的数据报表,基于Java开发出来一个BI系统,通过这个系统把各种存储好的数据暴露给前端,允许前端基于各种条件对存储好的数据进行复杂的筛选和分析,如下图所示。
刚开始上线系统时候的部署架构
刚开始的时候这个BI系统使用的商家是不多的,因为大家要知道,即使在一个庞大的互联网大厂里,虽然大厂本身积累了大量商家,但是要针对他们上线一个付费产品,刚开始未必所有人都买账,所以一开始系统上线大概就少数商家在使用,比如就几千个商家。
刚开始系统部署的非常简单,就是用几台机器来部署了上述的BI系统,机器都是普通的4核8G的配置
在这个配置之下,一般来说给堆内存中的新生代分配的内存都在1.5G左右,Eden区大概也就1G左右的空间,如下图所示。
技术痛点:实时自动刷新报表 + 大数据量报表
突然使用系统的商家数量开始暴涨的时候,突然使用系统的商家开始越来越多,给大家举个例子,当商家的数量级达到几万的时候。
此时要给大家说明一个此类BI系统的特点,就是在BI系统中有一种数据报表,他是支持前端页面有一个JS脚本,自动每隔几秒钟就发送请求到后台刷新一下数据的,这种报表称之为“实时数据报表”,如下图所示。
那么大家可以设想一下,假设仅仅就几万商家作为你的系统用户,很可能同一时间打开那个实时报表的商家就有几千个
然后每个商家打开实时报表之后,前端页面都会每隔几秒钟发送请求到后台来加载最新数据
基本上会出现你BI系统部署的每台机器每秒的请求会达到几百个,这里我们假设就是每秒500个请求吧。
然后每个请求会加载出来一张报表需要的大量数据,因为BI系统可能还需要针对那些数据进行内存中的现场计算加工一下,才能返回给前端页面展示。
根据我们之前的测算,每个请求大概需要加载出来100kb的数据进行计算,因此每秒500个请求,就需要加载出来50MB的数据到内存中进行计算,如下图所示。
没什么大影响的频繁Young GC
其实大家都已经发现上述系统的问题了,在上述系统运行模型下,基本上每秒会加载50MB的数据到Eden区中
只要区区20s,就会迅速填满Eden区,然后触发一次Young GC对新生代进行垃圾回收。
当然1G左右的Eden进行Young GC其实速度相对是比较快的,可能也就几十ms的时间就可以搞定了
所以之前也分析过,其实对系统性能影响并不大,而且上述BI系统场景下,基本上每次Young GC后存活对象可能就几十MB,甚至是几MB。
所以如果仅仅只是这样的话,那么大家可能会看到如下场景,BI系统运行20s过后,就会突然卡顿个10ms,但是对终端用户和系统性能几乎是没有影响的,如下图。
模拟代码的JVM参数设置
接着我们会用一段程序来模拟出上述BI系统那种频繁Young GC的一个场景,此时JVM参数如下所示:
-XX:NewSize=104857600 -XX:MaxNewSize=104857600 -XX:InitialHeapSize=209715200 -XX:MaxHeapSize=209715200 -XX:SurvivorRatio=8 -XX:MaxTenuringThreshold=15 -XX:PretenureSizeThreshold=3145728 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:gc.log
大家只要注意一下上述我们把堆内存设置为了200MB,把年轻代设置为了100MB,然后Eden区是80MB,每块Survivor区是10MB,老年代也是100MB。
我们把案例中的内存大小适当缩小了一些,这样方便大家在本地windows电脑来运行试验。
示例程序
针对这段示例程序给大家做一点说明。
首先看第一行代码:Thread.sleep(30000);
程序刚启动,必须得先让我们找到这个程序的PID,也就是进程ID,然后再执行jstat命令来观察程序运行时JVM的状态。
接着看loadData()方法内的代码,其实非常简单,他会循环50次,模拟每秒50个请求
然后每次请求会分配一个100KB的数组,模拟每次请求会从数据存储中加载出来100KB的数据。接着会休眠1秒钟,模拟这一切都是发生在1秒内的。
其实这些对象都是短生存周期的对象,所以方法运行结束直接对象都是垃圾,随时可以回收的。
然后在main()方法里有一个while(true)循环,模拟系统按照每秒钟50个请求,每个请求加载100KB数据的方式不停的运行,除非我们手动终止程序,否则永不停歇。
通过jstat观察程序的运行状态
接着我们使用预订的JVM参数启动程序,此时程序会先进入一个30秒的休眠状态,此时尽快执行jps命令,查看一下我们启动程序的进程ID,如下图所示:
此时会发现我们运行的Demo1这个程序的JVM进程ID是51464。
然后尽快执行下述jstat命令:jstat -gc 51464 1000 1000
他的意思就是针对51464这个进程统计JVM运行状态,同时每隔1秒钟打印一次统计信息,连续打印1000次。
然后我们就让jstat开始统计运行,每隔一秒他都会打印一行新的统计信息,过了几十秒后可以看到如下图所示的统计信息:
接着我们一点点来分析这个图。首先我们先看如下图所示的一段信息:
这个EU大家应该还记得,就是之前我们所说的Eden区被使用的容量,可以发现他刚开始是3MB左右的内存使用量
接着从我们程序开始运行,会发现每秒钟都会有对象增长,从3MB左右到7MB左右,接着是12MB,17MB,22MB,每秒都会新增5MB左右的对象。
这个跟我们写的代码是完全吻合的,我们就是每秒钟会增加5mB左右的对象。
然后当Eden区使用量达到70多MB的时候,再要分配5MB的对象就失败了,此时就会触发一次Young GC,然后大家继续看下面的图:
注意看上面红圈里的内容,大家会发现,Eden区的使用量从70多MB降低为了1MB多,这就是因为一次Young GC直接回收掉了大部分对象。
所以我们现在就知道了,针对这个代码示例,可以清晰的从jstat中看出来,对象增速大致为每秒5MB左右,大致在十几秒左右会触发一次Young GC
这个就是Young GC的触发频率,以及每次Young GC的耗时,大家看下图:
上图清晰告诉你了,一次Young GC回收70多MB对象,大概就1毫秒,所以大家想想,Young GC其实是很快的,即使回收800MB的对象,也就10毫秒那样。
所以你想如果是线上系统,他Eden区800MB的话,每秒新增对象50MB,十多秒一次Young GC,也就10毫秒左右,系统卡顿10毫秒,几乎没什么大影响的。
所以我们继续推论,在这个示例中,80MB的Eden区,每秒新增对象5MB,大概十多秒触发一次Young GC,每次Young GC耗时在1毫秒左右。
那么每次Young GC过后存活的对象呢?
简单看上上图,S1U就是Survivor中被使用的内存,之前一直是0,在一次Young GC过后变成了675KB,所以一次Young GC后也就存活675KB的对象而已,轻松放入10MB的Survivor中。
而且大家注意上图中的OU,那是老年代被使用的内存量,在Young GC前后都是0
这说明这个系统运行良好,Young GC都不会导致对象进入老年代,这就几乎不需要什么优化了。因为几乎可以默认老年代对象增速为0,Full GC发生频率趋向于0,对系统无影响。
所以大家回顾一下,通过一个示例程序的运行,是不是可以通过jstat分析出来以下信息:
新生代对象增长的速率
Young GC的触发频率
Young GC的耗时
每次Young GC后有多少对象是存活下来的
每次Young GC过后有多少对象进入了老年代
老年代对象增长的速率
Full GC的触发频率
Full GC的耗时
案例实战:每日百亿数据量的实时分析引擎,如何定位和解决频繁Full GC问题?
一个日处理上亿数据的计算系统
简单来说,这个系统就是会不停的从MySQL数据库以及其他数据源里提取大量的数据加载到自己的JVM内存里来进行计算处理,如下图所示。
这个数据计算系统会不停的通过SQL语句和其他方式从各种数据存储中提取数据到内存中来进行计算,大致当时的生产负载是每分钟大概需要执行500次数据提取和计算的任务。
但这是一套分布式运行的系统,所以生产环境部署了多台机器,每台机器大概每分钟负责执行100次数据提取和计算的任务。
每次会提取大概1万条左右的数据到内存里来计算,平均每次计算大概需要耗费10秒左右的时间
然后每台机器是4核8G的配置,JVM内存给了4G,其中新生代和老年代分别是1.5G的内存空间,大家看下图。
这个系统到底多快会塞满新生代?
现在明确了一些核心数据,接着我们来看看这个系统到底多快会塞满新生代的内存空间?
既然这个系统每台机器上部署的实例,每分钟会执行100次数据计算任务,每次是1万条数据需要计算10秒的时间,那么我们来看看每次1万条数据大概会占用多大的内存空间?
这里每条数据都是比较大的,大概每条数据包含了平均20个字段,可以认为平均每条数据在1KB左右的大小。
那么每次计算任务的1万条数据就对应了10MB的大小。所以大家此时可以思考一下,如果新生代是按照8:1:1的比例来分配Eden和两块Survivor的区域,那么大体上来说,Eden区就是1.2GB,每块Survivor区域在100MB左右,如下图。
基本上按照这个内存大小而言,大家会发现,每次执行一个计算任务,就会在Eden区里分配10MB左右的对象
一分钟大概对应100次计算任务,基本上一分钟过后,Eden区里就全是对象,基本就全满了。
所以说,回答这个小节的问题,新生代里的Eden区,基本上1分钟左右就迅速填满了。
触发Minor GC的时候会有多少对象进入老年代?
此时假设新生代的Eden区在1分钟过后都塞满对象了,然后在接着继续执行计算任务的时候,势必会导致需要进行Minor GC回收一部分的垃圾对象。
那么上篇文章给大家讲过这里在执行Minor GC之前会先进行的检查。
首先第一步,先看看老年代的可用内存空间是否大于新生代全部对象?
看下图,此时老年代是空的,大概有1.5G的可用内存空间,新生代的Eden区大概算他有1.2G的对象好了。
此时会发现老年代的可用内存空间有1.5GB,新生代的对象总共有1.2GB,即使一次Minor GC过后,全部对象都存活,老年代也能放的下的,那么此时就会直接执行Minor GC了。
那么此时Eden区里有多少对象还是存活的,无法被垃圾回收呢?
大家可以考虑一下之前说的那个点,每个计算任务1万条数据需要计算10秒钟,所以假设此时80个计算任务都执行结束了,但是还有20个计算任务共计200MB的数据,还在计算中,那么此时就是200MB的对象是存活的,不能被垃圾回收掉,然后有1GB的对象是可以垃圾回收的,大家看下图。
此时一次Minor GC就会回收掉1GB的对象,然后200MB的对象能放入Survivor区吗?
不能!
因为任何一块Survivor区实际上就100MB的空间,此时就会通过空间担保机制,让这200MB对象直接进入老年代去,占用里面200MB内存空间,然后Eden区就清空了,大家看下图。
系统运行多久,老年代大概就会填满?
那么大家想一下,这个系统大概运行多久,老年代会填满呢?
按照上述计算,每分钟都是一个轮回,大概算下来是每分钟都会把新生代的Eden区填满,然后触发一次Minor GC,然后大概都会有200MB左右的数据进入老年代。
那么大家可以想一下,假设现在2分钟运行过去了,此时老年代已经有400MB内存被占用了,只有1.1GB的内存可用,此时如果第3分钟运行完毕,又要进行Minor GC会做什么检查呢?
如下图:
此时会先检查老年代可用空间是否大于新生代全部对象,此时老年代可用空间1.1GB,新生代对象有1.2GB,那么此时假设一次Minor GC过后新生代对象全部存活,老年代是放不下的,那么此时就得看看一个参数是否打开了 。
如果“-XX:-HandlePromotionFailure”参数被打开了,当然一般都会打开,此时会进入第二步检查,就是看看老年代可用空间是否大于历次Minor GC过后进入老年代的对象的平均大小。
我们已经计算过了,大概每分钟会执行一次Minor GC,每次大概200MB对象会进入老年代。
那么此时发现老年代的1.1GB空间,是大于每次Minor GC后平均200MB对象进入老年代的大小的,所以基本可以推测,本次Minor GC后大概率还是有200MB对象进入老年代,1.1G可用空间是足够的。
所以此时就会放心执行一次Minor GC,然后又是200MB对象进入老年代。
转折点大概在运行了7分钟过后,7次Minor GC执行过后,大概1.4G对象进入老年代,老年代剩余空间就不到100MB了,几乎快满了,如下图。
这个系统运行多久,老年代会触发1次Full GC?
大概在第8分钟运行结束的时候,新生代又满了,执行Minor GC之前进行检查,此时发现老年代只有100MB内存空间了,比之前每次Minor GC后进入老年代的200MB对象要小,此时就会直接触发一次Full GC。
Full GC会把老年代的垃圾对象都给回收了,假设此时老年代被占据的1.4G空间里,全部都是可以回收的对象,那么此时一次性就会把这些对象都给回收了,如下图。
然后接着就会执行Minor GC,此时Eden区情况,200MB对象再次进入老年代,之前的Full GC就是为这些新生代本次Minor GC要进入老年代的对象准备的,如下图。
按照这个运行模型,基本上平均就是七八分钟一次Full GC,这个频率就相当高了。因为每次Full GC速度都是很慢的,性能很差
该案例应该如何进行JVM优化?
相信通过这个案例,大家结合图一路看下来,对新生代和老年代如何配合使用,然后什么情况下触发Minor GC和Full GC,什么情况下会导致频繁的Minor GC和Full GC,大家都有了更加深层次和透彻的理解了。
对这个系统,其实要优化也是很简单的,因为这个系统是数据计算系统,每次Minor GC的时候,必然会有一批数据没计算完毕,但是按照现有的内存模型,最大的问题,其实就是 每次Survivor区域放不下存活对象。
所以当时我们就是对生产系统进行了调整,增加了新生代的内存比例,3GB左右的堆内存,其中2GB分配给新生代,1GB留给老年代
这样Survivor区大概就是200MB,每次刚好能放得下Minor GC过后存活的对象了,如下图所示。
只要每次Minor GC过后200MB存活对象可以放Survivor区域,那么等下一次Minor GC的时候,这个Survivor区的对象对应的计算任务早就结束了,都是可以回收的了,此时比如Eden区里1.6GB空间被占满了,然后Survivor1区里有200MB上一轮 Minor GC后存活的对象,如下图。
然后此时执行Minor GC,就会把Eden区里1.4GB对象回收掉,Survivor1区里的200MB对象也会回收掉,然后Eden区里剩余的200MB存活对象会放入Survivor2区里,如下图。
以此类推,基本上就很少对象会进入老年代中,老年代里的对象也不会太多的。
通过这个分析和优化,定时我们成功的把生产系统的老年代Full GC的频率从几分钟一次降低到了几个小时一次,大幅度提升了系统的性能,避免了频繁Full GC对系统运行的影响。
运行程序用的示例JVM参数
下面的参数唯一修改的就是“-XX:PretenureSizeThreshold”,把大对象阈值修改为了20MB,避免我们程序里分配的大对象直接进入老年代。
-XX:NewSize=104857600 -XX:MaxNewSize=104857600 -XX:InitialHeapSize=209715200 -XX:MaxHeapSize=209715200 -XX:SurvivorRatio=8 -XX:MaxTenuringThreshold=15 -XX:PretenureSizeThreshold=20971520 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:gc.log
示例程序
简单给大家解释一下上面的程序
大概意思其实就是,每秒钟都会执行一次loadData()方法,他会分配4个10MB的数组,但是都立马成为垃圾,但是会有data1和data2两个10MB的数组是被变量引用必须存活的,此时Eden区已经占用了六七十MB空间了,接着是data3变量依次指向了两个10MB的数组,这是为了在1s内触发Young GC的。
基于jstat分析程序运行的状态
接着我们基于jstat分析程序运行的状态,启动程序后立马采用jstat监控其运行状态可以看到如下的信息:
接着我们一点点来分析这个jvm的运行状态。首先我们先看如下一行截图:
在这里最后一行,可以清晰看到,程序运行起来之后,突然在一秒内就发生了一次Young GC,这是为什么呢?
很简单,按照我们上述的代码,他一定会在一秒内触发一次Young GC的。
Young GC过后,我们发现S1U,也就是一个Survivor区中有587KB的存活对象,这应该就是那些未知对象了。
然后我们明显看到在OU中多出来了30MB左右的对象,因此可以确定,在这次Young GC的时候,有30MB的对象存活了,此时因为Survivor区域放不下,所以直接进入老年代了。
我们接着看下面的截图:
大家看上图中红圈的部分,很明显每秒会发生一次Young GC,都会导致20MB~30MB左右的对象进入老年代
因为每次Young GC都会存活下来这么多对象,但是Survivor区域是放不下的,所以都会直接进入老年代。
此时看到老年代的对象占用从30KB一路到60MB左右,此时突然在60MB之后下一秒,明显发生了一次Full GC,对老年代进行了垃圾回收,因为此时老年代重新变成30MB了。
为啥会这样?
很简单,老年代总共就100MB左右,已经占用了60MB了,此时如果发生一次Young GC,有30MB存活对象要放入老年代的话,你还要放30MB对象,明显老年代就要不够了,此时必须会进行Full GC,回收掉之前那60MB对象,然后再放入进去新的30MB对象。
所以大家可以看到,按照我们的这段代码,几乎是每秒新增80MB左右,触发每秒1次Young GC,每次Young GC后存活下来20MB30MB的对象,老年代每秒新增20MB30MB的对象,触发老年代几乎三秒一次Full GC,是不是跟我们上面的案例中分析的场景很类似?Young GC太频繁,而且每次GC后存活对象太多,频繁进入老年代,频繁触发老年代的GC。
那么Young GC和Full GC的耗时呢?看下图:
大家看上图,有没有发现Young GC特别坑爹,28次Young GC,结果耗费了180毫秒,平均下来一次Young GC要6毫秒左右。但是14次Full GC才耗费34毫秒,平均下来一次Full GC才耗费两三毫秒。这是为什么呢?
很简单,按照上述程序,每次Full GC都是由Young GC触发的,因为Young GC过后存活对象太多要放入老年代,老年代内存不够了触发Full GC,所以必须得等Full GC执行完毕了,Young GC才能把存活对象放入老年代,才算结束。这就导致Young GC也是速度非常慢。
对JVM性能进行优化
接着我们按照之前学习的思路对JVM进行优化,很简单,他最大的问题就是每次Young GC过后存活对象太多了,导致频繁进入老年代,频繁触发Full GC
我们只需要调大年轻代的内存空间,增加Survivor的内存即可,看如下JVM参数:
-XX:NewSize=209715200 -XX:MaxNewSize=209715200 -XX:InitialHeapSize=314572800 -XX:MaxHeapSize=314572800 -XX:SurvivorRatio=2 -XX:MaxTenuringThreshold=15 -XX:PretenureSizeThreshold=20971520 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:gc.log
我们把堆大小调大为了300MB,年轻代给了200MB,同时“-XX:SurvivorRatio=2”表明,Eden:Survivor:Survivor的比例为2:1:1,所以Eden区是100MB,每个Survivor区是50MB,老年代也是100MB。
接着我们用这个JVM参数运行程序,用jstat来监控其运行状态如下:
在上述截图里,大家可以清晰看到,每秒的Young gC过后,都会有20MB左右的存活对象进入Survivor,但是每个Survivor区都是50MB的大小,因此可以轻松容纳,而且一般不会过50%的动态年龄判定的阈值。
我们可以清晰看到每秒触发Yuong GC过后,几乎就没有对象会进入老年代,最终就600KB的对象进入了老年代里,其他就没有对象进入老年代了。
再看下面的截图:
我们可以看到,只有Young GC,没有Full GC,而且11次Young GC才不过9毫秒,平均一次GC1毫秒都不到,没有Full GC干扰之后,Young GC的性能极高。
所以,其实这个案例就优化成功了,同样的程序,仅仅是调整了内存分配比例,立马就大幅度提升了JVM的性能,几乎把Full GC给消灭掉了。