背景:后台定时任务脚本每天凌晨5点30会执行一个批量扫库做业务的逻辑。
gc错误日志:
2017-07-05T05:30:54.408+0800: 518534.458: [CMS-concurrent-mark-start] 2017-07-05T05:30:55.279+0800: 518535.329: [GC 518535.329: [ParNew: 838848K->838848K(1118464K), 0.0000270 secs] [CMS-concurrent-mark: 1.564/1.576 secs] [Times: user=10.88 sys=0.31, real=1.57 secs] (concurrent mode failure): 2720535K->2719116K(2796224K), 13.3742340 secs] 3559383K->2719116K(3914688K), [CMS Perm : 38833K->38824K(524288K)], 13.3748020 secs] [Times: user=16.19 sys=0.00, real=13.37 secs] 2017-07-05T05:31:08.659+0800: 518548.710: [GC [1 CMS-initial-mark: 2719116K(2796224K)] 2733442K(3914688K), 0.0065150 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 2017-07-05T05:31:08.666+0800: 518548.716: [CMS-concurrent-mark-start] 2017-07-05T05:31:09.528+0800: 518549.578: [GC 518549.578: [ParNew: 838848K->19737K(1118464K), 0.0055800 secs] 3557964K->2738853K(3914688K), 0.0060390 secs] [Times: user=0.09 sys=0.00, real=0.01 secs] [CMS-concurrent-mark: 1.644/1.659 secs] [Times: user=14.15 sys=0.84, real=1.66 secs] 2017-07-05T05:31:10.326+0800: 518550.376: [CMS-concurrent-preclean-start] 2017-07-05T05:31:10.341+0800: 518550.391: [CMS-concurrent-preclean: 0.015/0.015 secs] [Times: user=0.05 sys=0.02, real=0.02 secs] 2017-07-05T05:31:10.341+0800: 518550.391: [CMS-concurrent-abortable-preclean-start]
得知导致concurrent mode failure的原因有是: there was not enough space in the CMS generation to promote the worst case surviving young generation objects. We name this failure as “full promotion guarantee failure”
解决的方案有: The concurrent mode failure can either be avoided increasing the tenured generation size or initiating the CMS collection at a lesser heap occupancy by setting CMSInitiatingOccupancyFraction to a lower value and setting UseCMSInitiatingOccupancyOnly to true.
第二种方案需要综合考虑下,因为如果设置的CMSInitiatingOccupancyFraction过低有可能导致频繁的cms 降低性能。[参考不建议3g下配置cms:why no cms under 3G]
问题排查:
1 jvm参数配置 -Xmx4096m -Xms2048m -XX:CMSInitiatingOccupancyFraction=70 -XX:+UseCMSCompactAtFullCollection -XX:MaxTenuringThreshold=10 -XX:-UseAdaptiveSizePolicy -XX:PermSize=512M -XX:MaxPermSize=1024M -XX:SurvivorRatio=3 -XX:NewRatio=2 -XX:+PrintGCDateStamps -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails 几乎没什么问题
2 从报警时间看每天凌晨5点30报警一次, 应该是定时任务的问题。
该问题很容易排查,服务是个脚本服务,线上业务逻辑几乎没有,所以根据时间点找到定时任务的业务逻辑,就可以分析出来问题。
业务代码:
int batchNumber = 1; int realCount = 0; int offset = 0; int limit = 999; int totalCount = 0; //初始化20个大小的线程池 ExecutorService service = Executors.newFixedThreadPool(20); while (true) { LogUtils.info(logger, "{0},{1}->{2}", batchNumber, offset, (offset + limit)); try { //分页查询 Set<String> result = query(offset, limit); realCount = result.size(); //将查询出的数据放入线程池执行 service.execute(new AAAAAAA(result, batchNumber)); } catch (Exception e) { LogUtils.error(logger, e, "exception,batch:{0},offset:{1},count:{2}", batchNumber, offset, limit); break; } totalCount += realCount; if (realCount < limit) { break; } batchNumber++; offset += limit; } service.shutdown();
用了一个固定20个线程的线程池,循环执行每次从数据库里面取出来999条数据放到线程池里面去跑
分析
newFixedThreadPool底层用了一个
LinkedBlockingQueue无限队列,而我的数据有2kw+条,这样死循环取数据放到队列里面没有把内存撑爆算好的吧??? 最后换成
BlockingQueue<Runnable> queue = new ArrayBlockingQueue<Runnable>(20); ThreadPoolExecutor service = new ThreadPoolExecutor(20, 20, 1, TimeUnit.HOURS, queue, new ThreadPoolExecutor.CallerRunsPolicy());
用了个固定长度的队列,而且失败策略用的callerruns,可以理解为不能执行并且不能加入等待队列的时候主线程会直接跑run方法,会造成多线程变单线程,降低效率。
明天看看效果如何。