記錄一次concurrent mode failure問題排查過程以及解決思路
背景:後臺定時任務腳本每天淩晨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.01sys=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.15sys=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]
借鑒於:understanding-cms-gc-logs
得知導致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方法,會造成多線程變單線程,降低效率。
明天看看效果如何。
記錄一次concurrent mode failure問題排查過程以及解決思路