一次由groovy引起的fullGC问题排查

见贤思齐

一、问题背景二、分析过程2.1参数配置2.2定位过程2.3JVM分析2.4问题分析三、解决方案一、问题背景prometheus监控报警生效后，某服务每天的上午8-12点间会有fullGC的报警；排查并解决该问题；二、分析过程2.1参数配置JVM参数配置如下:-Xms3g -Xmx3g -Xmn1g -XX:MetaspaceSize=128m -XXarallelGCThreads=5 -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+UseCMSCompactAtFullCollection -XX:CMSInitiatingOccupancyFraction=80 -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+HeapDumpOnOutOfMemoryError 新生代大小：1G；新生代垃圾收集器：ParNewGC；老年代大小：2G；老年代垃圾收集器：ConcMarkSweepGC；CMS触发条件：老年代内存占用达到80%及以上；2.2定位问题1.由于报警的时间点都集中在上午的8-12点之间，怀疑是由于某个定时任务造成的；2.定位具体的定时任务，有两个定时任务的时间设置基本满足；任务1: 更新客户信息  CustomerScheduleJobService.updateCustomerDataDaily  0 0/30 8,9,10,11,12 * * ?任务2: 创建客户任务   CustomerStaffScheduleJobService.jobCreateTask  0 10,40 7,8,9,10,11 * * ?3.确定具体的任务确认的两个思路:1.通过日志确认定时任务的执行时长等；2.将2个定时任务分别指定不同的机器执行观察；排查任务执行时间：任务1:很快，几乎不处理业务逻辑；[03-09 08:00:00 062 INFO ] [] [] [] [customerDataStat-pool-0] bll.customer.CustomerUpdateInfoDailyBll - (123) logid=6907112718471909376 [BizCustomerBll.updateCustomerDataDaily] thread begin...Ip: 10.151.49.157[03-09 08:01:25 476 INFO ] [] [] [] [customerDataStat-pool-0] bll.customer.CustomerUpdateInfoDailyBll - (125) logid=6907112718471909376 [BizCustomerBll.updateCustomerDataDaily] end total=0Ip: 10.151.49.157任务2:执行约35分钟时间；8:10分开始，8:45分结束；[03-09 08:45:08 458 INFO ] [] [] [] [pool-4-thread-20] bll.task.CreateCustomerTaskBll - (109) logid=6907115234995589120 method=jobCreateTask msg=end queryRuleNum=7 queryCustomerNum=15962 createTaskCustomerNum=238 createTaskCount=271Ip: 10.151.49.157基本确定为第二个定时任务导致FullGC;2.3JVM分析2.3.1单天监控图内存趋势GC趋势2.3.2报警时间段监控图内存趋势GC趋势2.3.3图表分析2.3.3.1老年代变化现象1.任务执行过程中：老年代有明显增长，并且FullGC后并没有特别明显的下降，只有些许下降；2.任务执行结束后：下次任务开始执行，进行FullGC后，会降到跟其他机器一样的水平，甚至内存占用更低；备注新生代到老年代的几种情况1:大对象；2:年龄足够长，cms没有设置，默认是6，通过jinfo确认也是6；3:suvivor区不足以存放YGC后的存活对象，直接使用担保策略晋升到老年代；分析任务执行过程中，YGC平均1分钟执行5次，很多对象都会达到最大晋升年龄6，晋升到老年代；并且由于任务没有结束，对象还有引用，所以FullGC之后并没有明显下降；上次任务结束后，老年代并没有像suvivor区一样有一段时间的低内存占用，主要是直到下次任务开始后才会触发新一次的FullGC，触发后，老年代的对象由于任务结束后没有引用了，所以会正常回收；2.3.3.2survivor区变化suvivor区内存总共100M，任务执行过程中，平均占用80M；高的时候会飙升到90以上，所以这个过程中YGC也变得很频繁，平均1分钟5次；2.3.3.3非堆内存/方法区/compressedclasscach变化使用jstat分别统计了两台机器的gc统计，两者最大的区别在于执行过定时任务的机器的MC(方法区大小)以及CCSC(压缩类空间大小)明显比没有执行过定时任务的机器高很多；任务执行过程中方法区的内存占用会跟老年代的曲线保持一致，这几个区的回收也是靠老年代，这个通过grafana平台的监控图也可以看出来；2.3.3.4dump文件分析groovy相关的类占比57.57%；2.4参数配置java与groovy版本java version "1.8.0_191"        org.codehaus.groovy        2.4.15代码中使用到groovy的地方：同样是这个定时任务，下发任务时，表达式检验是否满足下发条件，表达式是用groovy进行处理的；public class GroovyShellUtils {    private static LoggerHelper logger = LoggerHelper.getLoggerHelper(GroovyShellUtils.class);    public static boolean explain(String scriptText) {        try {            GroovyShell groovyShell = new GroovyShell();            Object evaluate = groovyShell.evaluate(scriptText);            return (boolean) evaluate;        } catch (Exception e) {            logger.error("", e);        }        return false;    }}// 使用：for (String rule : rules) {    boolean res = GroovyShellUtils.explain(rule);}基本上可以定位问题在groovy脚本的加载处，groovy不合理使用会导致，动态生成很多新类，使得metaspace的不断被占用；class对象在1.8及以后存放在metaspace中，也就是堆外内存。groovy每执行一次，会将传入的文本动态加载成一个脚本类，入参是文本时，生成的文件名中包含了一个自增的数值，也就是每执行一次都会动态生成一个新类，1个用户7个任务规则校验*15962个用户=111734个protected synchronized String generateScriptName() {    return "Script" + (++counter) + ".groovy";}GroovyShell在内部，它使用groovy.lang.GroovyClassLoader，这是在运行时编译和加载类的核心。GroovyClassLoader保留对其创建的所有类的引用，而class对象只有在被加载的classloader被回收的时候才会被回收，因此很容易造成内存泄漏；综上分析，groovy错误的使用方式导致class对象常驻堆外内存且随着调用频率增长。三、解决方案1、每个脚本共用一个GroovyShell对象，不能使用for的方式，循环创建使用；2、每次执行完释放对象shell.getClassLoader().clearCache()；