AviatorEvaluator执行脚本导致Metaspace不足引发频繁 Full GC
152 浏览量
2021-01-07
09:43:04
上传
评论
收藏 526KB PDF 举报
AviatorEvaluator执行脚本导致执行脚本导致Metaspace不足引发频繁不足引发频繁 Full GC
AviatorEvaluator执行脚本导致执行脚本导致Metaspace不足引发频繁不足引发频繁 Full GC故障机经过
故障机经过故障机经过
数据分析&特征平台DMP 最近频繁发生Full GC, 引发集群卡顿，导致经常超时，按照常规的方法，肯定是先看GC 日志
2020-02-17T10:17:24.672+0800: 48172.920: [GC (Allocation Failure) 2020-02-17T10:17:24.672+0800: 48172.920: [ParNew: 1756536K->14685K(1922432K), 0.0272831 secs] 1850643K->108791K(4019584K), 0.0275241
secs] [Times: user=0.09 sys=0.00, real=0.02 secs] 2020-02-17T10:18:54.306+0800: 48262.553: [Full GC (Metadata GC Threshold) 2020-02-17T10:18:54.306+0800: 48262.554: [CMS: 94106K->94283K(2097152K),
0.4276851 secs] 1646355K->94283K(4019584K), [Metaspace: 131757K->131757K(1269760K)], 0.4930214 secs] [Times: user=0.49 sys=0.00, real=0.49 secs] 2020-02-17T10:18:54.800+0800: 48263.048: [GC (CMS
Initial Mark) [1 CMS-initial-mark: 94283K(2097152K)] 94366K(4019584K), 0.0018632 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 2020-02-17T10:18:54.802+0800: 48263.050: [CMS-concurrent-mark-start] 2020-02-
17T10:18:54.874+0800: 48263.122: [CMS-concurrent-mark: 0.072/0.072 secs] [Times: user=0.10 sys=0.00, real=0.07 secs] 2020-02-17T10:18:54.874+0800: 48263.122: [CMS-concurrent-preclean-start] 2020-02-
17T10:18:54.880+0800: 48263.128: [CMS-concurrent-preclean: 0.006/0.006 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 2020-02-17T10:18:54.880+0800: 48263.128: [CMS-concurrent-abortable-preclean-start]
CMS: abort preclean due to time 2020-02-17T10:18:59.965+0800: 48268.213: [CMS-concurrent-abortable-preclean: 0.357/5.085 secs] [Times: user=0.64 sys=0.07, real=5.09 secs] 2020-02-17T10:18:59.966+0800:
48268.214: [GC (CMS Final Remark) [YG occupancy: 109954 K (1922432 K)]2020-02-17T10:18:59.966+0800: 48268.214: [GC (CMS Final Remark) 2020-02-17T10:18:59.966+0800: 48268.214: [ParNew: 109954K-
>10530K(1922432K), 0.0069004 secs] 204238K->104814K(4019584K), 0.0070590 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 2020-02-17T10:18:59.974+0800: 48268.221: [Rescan (parallel) , 0.0027595
secs]2020-02-17T10:18:59.976+0800: 48268.224: [weak refs processing, 0.0000270 secs]2020-02-17T10:18:59.976+0800: 48268.224: [class unloading, 0.0173472 secs]2020-02-17T10:18:59.994+0800: 48268.242:
[scrub symbol table, 0.0091774 secs]2020-02-17T10:19:00.003+0800: 48268.251: [scrub string table, 0.0012562 secs][1 CMS-remark: 94283K(2097152K)] 104814K(4019584K), 0.0378180 secs] [Times: user=0.07
sys=0.00, real=0.03 secs] 2020-02-17T10:19:00.004+0800: 48268.252: [CMS-concurrent-sweep-start] 2020-02-17T10:19:00.022+0800: 48268.270: [CMS-concurrent-sweep: 0.016/0.017 secs] [Times: user=0.02 sys=0.00,
real=0.02 secs] 2020-02-17T10:19:00.022+0800: 48268.270: [CMS-concurrent-reset-start] 2020-02-17T10:19:00.026+0800: 48268.274: [CMS-concurrent-reset: 0.005/0.005 secs] [Times: user=0.00 sys=0.00, real=0.01
secs] 2020-02-17T10:20:40.128+0800: 48368.376: [GC (Allocation Failure) 2020-02-17T10:20:40.128+0800: 48368.376: [ParNew: 1758242K->8224K(1922432K), 0.0183614 secs] 1852225K->102207K(4019584K),
0.0186059 secs] [Times: user=0.07 sys=0.00, real=0.02 secs] 2020-02-17T10:22:16.160+0800: 48464.408: [GC (Allocation Failure) 2020-02-17T10:22:16.160+0800: 48464.408: [ParNew: 1755936K->14574K(1922432K),
0.0241362 secs] 1849919K->108557K(4019584K), 0.0243800 secs] [Times: user=0.09 sys=0.00, real=0.02 secs]
通过关键字 Metadata GC Threshold 很明显看出来是 Metaspace不够了引发的Full GC, 看了一下启动脚本 -server -Xms4g -Xmx4g -XX:MetaspaceSize=256m -
XX:MaxMetaspaceSize=256m，感觉也不少小了 256M啊， 按照一般的思路 先增大一下 改成 512M，
XX:MetaspaceSize=512m -XX:MaxMetaspaceSize=512m
好了然后重启，然后 再去看下 GC 日志
2020-02-17T11:59:30.530+0800: 5770.687: [GC (Allocation Failure) 2020-02-17T11:59:30.531+0800: 5770.687: [ParNew: 1792024K->52115K(1922432K), 0.0567579 secs] 1866235K->126326K(4019584K), 0.0569325
secs] [Times: user=0.22 sys=0.00, real=0.06 secs] 2020-02-17T12:00:23.082+0800: 5823.239: [Full GC (Metadata GC Threshold) 2020-02-17T12:00:23.083+0800: 5823.239: [CMS: 74210K->75453K(2097152K),
0.3709796 secs] 1191513K->75453K(4019584K), [Metaspace: 217153K->217153K(1488896K)], 0.5101414 secs] [Times: user=0.49 sys=0.02, real=0.51 secs] 2020-02-17T12:00:23.595+0800: 5823.752: [GC (CMS Initial
Mark) [1 CMS-initial-mark: 75453K(2097152K)] 80589K(4019584K), 0.0014025 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2020-02-17T12:00:23.597+0800: 5823.753: [CMS-concurrent-mark-start] 2020-02-
17T12:00:23.670+0800: 5823.827: [CMS-concurrent-mark: 0.070/0.074 secs] [Times: user=0.11 sys=0.01, real=0.08 secs] 2020-02-17T12:00:23.670+0800: 5823.827: [CMS-concurrent-preclean-start] 2020-02-
17T12:00:23.676+0800: 5823.833: [CMS-concurrent-preclean: 0.005/0.006 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2020-02-17T12:00:23.676+0800: 5823.833: [CMS-concurrent-abortable-preclean-start] CMS:
abort preclean due to time 2020-02-17T12:00:28.747+0800: 5828.903: [CMS-concurrent-abortable-preclean: 0.348/5.071 secs] [Times: user=0.70 sys=0.09, real=5.07 secs] 2020-02-17T12:00:28.748+0800: 5828.904: [GC
(CMS Final Remark) [YG occupancy: 174871 K (1922432 K)]2020-02-17T12:00:28.748+0800: 5828.904: [GC (CMS Final Remark) 2020-02-17T12:00:28.748+0800: 5828.904: [ParNew: 174871K->34336K(1922432K),
0.0058048 secs] 250325K->109789K(4019584K), 0.0059220 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 2020-02-17T12:00:28.754+0800: 5828.910: [Rescan (parallel) , 0.0024441 secs]2020-02-
17T12:00:28.756+0800: 5828.913: [weak refs processing, 0.0000242 secs]2020-02-17T12:00:28.756+0800: 5828.913: [class unloading, 0.0141645 secs]2020-02-17T12:00:28.770+0800: 5828.927: [scrub symbol table,
0.0149135 secs]2020-02-17T12:00:28.785+0800: 5828.942: [scrub string table, 0.0010193 secs][1 CMS-remark: 75453K(2097152K)] 109789K(4019584K), 0.0387121 secs] [Times: user=0.06 sys=0.00, real=0.04 secs]
2020-02-17T12:00:28.786+0800: 5828.943: [CMS-concurrent-sweep-start] 2020-02-17T12:00:28.803+0800: 5828.959: [CMS-concurrent-sweep: 0.015/0.016 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 2020-02-
17T12:00:28.803+0800: 5828.959: [CMS-concurrent-reset-start] 2020-02-17T12:00:28.807+0800: 5828.964: [CMS-concurrent-reset: 0.004/0.004 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2020-02-
17T12:01:50.825+0800: 5910.981: [GC (Allocation Failure) 2020-02-17T12:01:50.825+0800: 5910.981: [ParNew: 1782048K->10925K(1922432K), 0.0166401 secs] 1857197K->86075K(4019584K), 0.0168483 secs]
[Times: user=0.06 sys=0.00, real=0.01 secs] 2020-02-17T12:02:50.594+0800: 5970.751: [GC (Allocation Failure) 2020-02-17T12:02:50.594+0800: 5970.751: [ParNew: 1758637K->16530K(1922432K), 0.0232256 secs]
1833787K->91679K(4019584K), 0.0234146 secs] [Times: user=0.09 sys=0.00, real=0.02 secs] 2020-02-17T12:04:07.688+0800: 6047.845: [GC (Allocation Failure) 2020-02-17T12:04:07.688+0800: 6047.845: [ParNew:
1764242K->23480K(1922432K), 0.0298658 secs] 1839391K->98629K(4019584K), 0.0300559 secs] [Times: user=0.11 sys=0.00, real=0.03 secs]
卧槽 他还没完了， 而且Metaspace 由 131757K 涨到了 217153K， 也基本快翻倍了。看了下 jstat 也比较奇葩
这个full gc 来的很突然。。。。。
好吧 他到底加载了啥呢，jmap -histo 打出来看看，不看不知道 一看吓一跳
漫山遍野的这个，，下面只是部分片段
5608: 1 32 Script_1581907910971_196210/919023170
5609: 1 32 Script_1581907910984_196211/2014081648
5610: 1 32 Script_1581907910984_196212/1051615301
5611: 1 32 Script_1581907910985_196213/1253180730
5612: 1 32 Script_1581907910985_196214/1970575446
5613: 1 32 Script_1581907911009_196215/761336634
5614: 1 32 Script_1581907911009_196216/498029164
5615: 1 32 Script_1581907911009_196217/945249795
5616: 1 32 Script_1581907911009_196218/575798139
5617: 1 32 Script_1581907911010_196219/126670024
5618: 1 32 Script_1581907911010_196220/1616366183
5619: 1 32 Script_1581907911010_196221/1651648296
5620: 1 32 Script_1581907911126_196222/1361222801
5621: 1 32 Script_1581907911126_196223/437794686
5622: 1 32 Script_1581907911126_196224/1046625305
5623: 1 32 Script_1581907911126_196225/1835664207
5624: 1 32 Script_1581907911127_196226/686414951
5625: 1 32 Script_1581907911127_196227/1938931139
5626: 1 32 Script_1581907911127_196228/1555879260
5627: 1 32 Script_1581907911149_196229/1825380803
5628: 1 32 Script_1581907911149_196230/1988208093
5629: 1 32 Script_1581907911149_196231/531911101
5630: 1 32 Script_1581907911149_196232/927256712
5631: 1 32 Script_1581907911150_196233/860083362
5632: 1 32 Script_1581907911150_196234/1217867866
5633: 1 32 Script_1581907911150_196235/1964226892
5634: 1 32 Script_1581907911172_196236/1183958563
5635: 1 32 Script_1581907911172_196237/31905867
5636: 1 32 Script_1581907911182_196238/1872279295
5637: 1 32 Script_1581907911182_196239/411183914
5638: 1 32 Script_1581907911183_196240/69649808
5639: 1 32 Script_1581907911190_196241/1256693698
5640: 1 32 Script_1581907911190_196242/1080121192
5641: 1 32 Script_1581907911190_196243/494593191
5642: 1 32 Script_1581907911190_196244/349508715
5643: 1 32 Script_1581907911190_196245/1648005308
5644: 1 32 Script_1581907911191_196246/682250628
5645: 1 32 Script_1581907911191_196247/1648351210
5646: 1 32 Script_1581907911219_196248/745851961
5647: 1 32 Script_1581907911219_196249/447851871
5648: 1 32 Script_1581907911219_196250/897859737
5649: 1 32 Script_1581907911219_196251/1592049776 5653,1 45%
资源评论
