Rare very big pause

Tue Dec 19 14:57:00 UTC 2017

Good day!

I'm trying to use Shenandoah GC from Fedora 27 at jdk8u151b12, and I have rare (one-two time per our) very big pause. Up to 0.5 seconds.

You can find a GC log bellow (it is log for 10 minutes where this sort of pause happened).

The pause had happened at 2017-12-19T12:11:03.965+0000 and was 446.259 ms

java runs with arguments:
-server -XX:-OmitStackTraceInFastThrow -Xmx6144m -XX:+UseShenandoahGC -XX:+AlwaysPreTouch -XX:-UseBiasedLocking -XX:+DisableExplicitGC -XX:+UseTransparentHugePages -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps

The log:
Concurrent marking triggered. Free: 552M, Free Threshold: 552M; Allocated: 552M, Alloc Threshold: 0M
2017-12-19T12:05:18.585+0000: 11876.106: [Pause Init Mark, 5.275 ms]
2017-12-19T12:05:18.590+0000: 11876.109: [Concurrent marking 5582M->5610M(6144M), 1093.063 ms]
2017-12-19T12:05:19.684+0000: 11877.203: [Pause Final MarkTotal Garbage: 4518M
Immediate Garbage: 1200M, 600 regions (28% of total)
Garbage to be collected: 2872M (63% of total), 1512 regions
Live objects to be evacuated: 147M
Live/garbage ratio in collected regions: 5%
 5610M->4412M(6144M), 38.723 ms]
2017-12-19T12:05:19.723+0000: 11877.243: [Concurrent evacuation 4413M->4577M(6144M), 130.382 ms]
2017-12-19T12:05:19.854+0000: 11877.373: [Pause Init Update Refs, 0.114 ms]
2017-12-19T12:05:19.854+0000: 11877.374: [Concurrent update references  4577M->4599M(6144M), 669.178 ms]
2017-12-19T12:05:20.524+0000: 11878.043: [Pause Final Update Refs 4599M->1578M(6144M), 2.454 ms]
2017-12-19T12:05:20.527+0000: 11878.046: [Concurrent reset bitmaps 1578M->1578M(6144M), 3.767 ms]
Capacity: 6144M, Peak Occupancy: 5610M, Lowest Free: 533M, Free Threshold: 184M
Adjusting free threshold to: 4% (245M)
Concurrent marking triggered. Free: 244M, Free Threshold: 245M; Allocated: 244M, Alloc Threshold: 0M
2017-12-19T12:06:26.485+0000: 11944.004: [Pause Init Mark, 3.089 ms]
2017-12-19T12:06:26.488+0000: 11944.007: [Concurrent marking 5892M->6134M(6144M), 956.447 ms]
2017-12-19T12:06:27.444+0000: 11944.964: [Concurrent precleaning 6134M->6136M(6144M), 1.746 ms]
2017-12-19T12:06:27.447+0000: 11944.966: [Pause Final MarkTotal Garbage: 5133M
Immediate Garbage: 2282M, 1141 regions (46% of total)
Garbage to be collected: 2535M (49% of total), 1311 regions
Live objects to be evacuated: 83M
Live/garbage ratio in collected regions: 3%
 6136M->3856M(6144M), 13.938 ms]
2017-12-19T12:06:27.465+0000: 11944.984: [Concurrent evacuation 3864M->4004M(6144M), 117.100 ms]
2017-12-19T12:06:27.583+0000: 11945.102: [Pause Init Update Refs, 0.106 ms]
2017-12-19T12:06:27.583+0000: 11945.103: [Concurrent update references  4006M->4392M(6144M), 807.411 ms]
2017-12-19T12:06:28.392+0000: 11945.911: [Pause Final Update Refs 4392M->1773M(6144M), 2.480 ms]
2017-12-19T12:06:28.394+0000: 11945.913: [Concurrent reset bitmaps 1773M->1775M(6144M), 5.338 ms]
Capacity: 6144M, Peak Occupancy: 6136M, Lowest Free: 7M, Free Threshold: 184M
Adjusting free threshold to: 7% (430M)
Concurrent marking triggered. Free: 428M, Free Threshold: 430M; Allocated: 428M, Alloc Threshold: 0M
2017-12-19T12:06:57.712+0000: 11975.232: [Pause Init Mark, 2.998 ms]
2017-12-19T12:06:57.716+0000: 11975.235: [Concurrent marking 5710M->5824M(6144M), 1137.936 ms]
2017-12-19T12:06:58.854+0000: 11976.374: [Pause Final MarkTotal Garbage: 4656M
Immediate Garbage: 1890M, 945 regions (43% of total)
Garbage to be collected: 2329M (50% of total), 1235 regions
Live objects to be evacuated: 139M
Live/garbage ratio in collected regions: 5%
 5824M->3936M(6144M), 12.464 ms]
2017-12-19T12:06:58.868+0000: 11976.387: [Concurrent evacuation 3943M->4086M(6144M), 110.411 ms]
2017-12-19T12:06:58.979+0000: 11976.498: [Pause Init Update Refs, 0.106 ms]
2017-12-19T12:06:58.979+0000: 11976.498: [Concurrent update references  4086M->4125M(6144M), 711.303 ms]
2017-12-19T12:06:59.691+0000: 11977.211: [Pause Final Update Refs 4125M->1656M(6144M), 2.317 ms]
2017-12-19T12:06:59.694+0000: 11977.213: [Concurrent reset bitmaps 1656M->1656M(6144M), 2.713 ms]
Capacity: 6144M, Peak Occupancy: 5824M, Lowest Free: 319M, Free Threshold: 184M
Concurrent marking triggered. Free: 430M, Free Threshold: 430M; Allocated: 430M, Alloc Threshold: 0M
2017-12-19T12:07:28.999+0000: 12006.518: [Pause Init Mark, 2.983 ms]
2017-12-19T12:07:29.002+0000: 12006.521: [Concurrent marking 5713M->5890M(6144M), 1230.274 ms]
2017-12-19T12:07:30.233+0000: 12007.753: [Pause Final MarkTotal Garbage: 4660M
Immediate Garbage: 1962M, 981 regions (45% of total)
Garbage to be collected: 2257M (48% of total), 1194 regions
Live objects to be evacuated: 128M
Live/garbage ratio in collected regions: 5%
 5890M->3930M(6144M), 11.268 ms]
2017-12-19T12:07:30.245+0000: 12007.764: [Concurrent evacuation 3932M->4066M(6144M), 111.081 ms]
2017-12-19T12:07:30.357+0000: 12007.876: [Pause Init Update Refs, 0.101 ms]
2017-12-19T12:07:30.357+0000: 12007.876: [Concurrent update references  4066M->4080M(6144M), 686.184 ms]
2017-12-19T12:07:31.044+0000: 12008.563: [Pause Final Update Refs 4080M->1694M(6144M), 2.311 ms]
2017-12-19T12:07:31.046+0000: 12008.565: [Concurrent reset bitmaps 1694M->1694M(6144M), 3.733 ms]
Capacity: 6144M, Peak Occupancy: 5890M, Lowest Free: 253M, Free Threshold: 184M
Concurrent marking triggered. Free: 429M, Free Threshold: 430M; Allocated: 429M, Alloc Threshold: 0M
2017-12-19T12:09:15.602+0000: 12113.121: [Pause Init Mark, 2.988 ms]
2017-12-19T12:09:15.605+0000: 12113.124: [Concurrent marking 5704M->5721M(6144M), 713.760 ms]
2017-12-19T12:09:16.319+0000: 12113.839: [Pause Final MarkTotal Garbage: 4948M
Immediate Garbage: 1667M, 834 regions (35% of total)
Garbage to be collected: 2964M (59% of total), 1525 regions
Live objects to be evacuated: 79M
Live/garbage ratio in collected regions: 2%
 5721M->4055M(6144M), 11.784 ms]
2017-12-19T12:09:16.332+0000: 12113.851: [Concurrent evacuation 4061M->4145M(6144M), 66.259 ms]
2017-12-19T12:09:16.399+0000: 12113.918: [Pause Init Update Refs, 0.104 ms]
2017-12-19T12:09:16.399+0000: 12113.918: [Concurrent update references  4145M->4159M(6144M), 409.740 ms]
2017-12-19T12:09:16.810+0000: 12114.329: [Pause Final Update Refs 4159M->1115M(6144M), 2.491 ms]
2017-12-19T12:09:16.812+0000: 12114.332: [Concurrent reset bitmaps 1115M->1115M(6144M), 4.700 ms]
Capacity: 6144M, Peak Occupancy: 5721M, Lowest Free: 422M, Free Threshold: 184M
Adjusting free threshold to: 4% (245M)
Concurrent marking triggered. Free: 238M, Free Threshold: 245M; Allocated: 238M, Alloc Threshold: 0M
2017-12-19T12:09:47.005+0000: 12144.524: [Pause Init Mark, 2.417 ms]
2017-12-19T12:09:47.008+0000: 12144.527: [Concurrent marking 5898M->5948M(6144M), 985.550 ms]
2017-12-19T12:09:47.994+0000: 12145.513: [Pause Final MarkTotal Garbage: 4900M
Immediate Garbage: 2342M, 1171 regions (51% of total)
Garbage to be collected: 2116M (43% of total), 1098 regions
Live objects to be evacuated: 78M
Live/garbage ratio in collected regions: 3%
 5948M->3608M(6144M), 37.561 ms]
2017-12-19T12:09:48.032+0000: 12145.551: [Concurrent evacuation 3609M->3696M(6144M), 68.148 ms]
2017-12-19T12:09:48.101+0000: 12145.620: [Pause Init Update Refs, 0.102 ms]
2017-12-19T12:09:48.101+0000: 12145.620: [Concurrent update references  3696M->3724M(6144M), 584.008 ms]
2017-12-19T12:09:48.686+0000: 12146.205: [Pause Final Update Refs 3724M->1530M(6144M), 2.221 ms]
2017-12-19T12:09:48.688+0000: 12146.207: [Concurrent reset bitmaps 1530M->1530M(6144M), 2.919 ms]
Capacity: 6144M, Peak Occupancy: 5948M, Lowest Free: 195M, Free Threshold: 184M
Concurrent marking triggered. Free: 245M, Free Threshold: 245M; Allocated: 245M, Alloc Threshold: 0M
2017-12-19T12:11:03.960+0000: 12221.481: [Pause Init Mark, 5.081 ms]
2017-12-19T12:11:03.965+0000: 12221.485: [Concurrent markingCancelling concurrent GC: Allocation Failure
 5887M->6130M(6144M), 653.310 ms]
Adjusting free threshold to: 14% (860M)
2017-12-19T12:11:04.620+0000: 12222.139: [Pause Final MarkTotal Garbage: 4889M
Immediate Garbage: 2018M, 1009 regions (44% of total)
Garbage to be collected: 2435M (49% of total), 1264 regions
Live objects to be evacuated: 87M
Live/garbage ratio in collected regions: 3%
 6130M->4114M(6144M), 446.259 ms]
2017-12-19T12:11:05.069+0000: 12222.594: [Concurrent evacuation 4118M->4251M(6144M), 116.424 ms]
2017-12-19T12:11:05.187+0000: 12222.706: [Pause Init Update Refs, 0.105 ms]
2017-12-19T12:11:05.187+0000: 12222.706: [Concurrent update references  4251M->4614M(6144M), 992.439 ms]
2017-12-19T12:11:06.180+0000: 12223.699: [Pause Final Update Refs 4614M->2092M(6144M), 2.380 ms]
2017-12-19T12:11:06.183+0000: 12223.702: [Concurrent reset bitmaps 2092M->2092M(6144M), 4.246 ms]
Capacity: 6144M, Peak Occupancy: 6130M, Lowest Free: 13M, Free Threshold: 184M
Adjusting free threshold to: 17% (1044M)
Concurrent marking triggered. Free: 1043M, Free Threshold: 1044M; Allocated: 1043M, Alloc Threshold: 0M
2017-12-19T12:11:23.829+0000: 12241.348: [Pause Init Mark, 2.962 ms]
2017-12-19T12:11:23.832+0000: 12241.351: [Concurrent marking 5094M->5122M(6144M), 700.227 ms]
2017-12-19T12:11:24.533+0000: 12242.052: [Pause Final MarkTotal Garbage: 4338M
Immediate Garbage: 2252M, 1126 regions (54% of total)
Garbage to be collected: 1771M (40% of total), 923 regions
Live objects to be evacuated: 73M
Live/garbage ratio in collected regions: 4%
 5122M->2872M(6144M), 12.196 ms]
2017-12-19T12:11:24.545+0000: 12242.065: [Concurrent evacuation 2876M->2958M(6144M), 63.041 ms]
2017-12-19T12:11:24.609+0000: 12242.128: [Pause Init Update Refs, 0.099 ms]
2017-12-19T12:11:24.609+0000: 12242.129: [Concurrent update references  2962M->2968M(6144M), 402.969 ms]
2017-12-19T12:11:25.013+0000: 12242.533: [Pause Final Update Refs 2968M->1124M(6144M), 2.222 ms]
2017-12-19T12:11:25.016+0000: 12242.535: [Concurrent reset bitmaps 1124M->1124M(6144M), 3.644 ms]
Capacity: 6144M, Peak Occupancy: 5122M, Lowest Free: 1021M, Free Threshold: 184M
Concurrent marking triggered. Free: 1043M, Free Threshold: 1044M; Allocated: 1043M, Alloc Threshold: 0M
2017-12-19T12:12:09.424+0000: 12286.943: [Pause Init Mark, 3.066 ms]
2017-12-19T12:12:09.427+0000: 12286.947: [Concurrent marking 5091M->5105M(6144M), 694.640 ms]
2017-12-19T12:12:10.123+0000: 12287.642: [Pause Final MarkTotal Garbage: 4338M
Immediate Garbage: 1980M, 990 regions (48% of total)
Garbage to be collected: 2044M (47% of total), 1062 regions
Live objects to be evacuated: 76M
Live/garbage ratio in collected regions: 3%
 5105M->3127M(6144M), 11.334 ms]
2017-12-19T12:12:10.134+0000: 12287.654: [Concurrent evacuation 3129M->3212M(6144M), 64.445 ms]
2017-12-19T12:12:10.200+0000: 12287.719: [Pause Init Update Refs, 0.106 ms]
2017-12-19T12:12:10.200+0000: 12287.719: [Concurrent update references  3216M->3224M(6144M), 405.975 ms]
2017-12-19T12:12:10.607+0000: 12288.126: [Pause Final Update Refs 3224M->1103M(6144M), 2.868 ms]
2017-12-19T12:12:10.610+0000: 12288.129: [Concurrent reset bitmaps 1103M->1103M(6144M), 4.004 ms]
Capacity: 6144M, Peak Occupancy: 5105M, Lowest Free: 1038M, Free Threshold: 184M
Concurrent marking triggered. Free: 1035M, Free Threshold: 1044M; Allocated: 1035M, Alloc Threshold: 0M
2017-12-19T12:13:10.975+0000: 12348.494: [Pause Init Mark, 3.064 ms]
2017-12-19T12:13:10.978+0000: 12348.497: [Concurrent marking 5099M->5257M(6144M), 1174.055 ms]
2017-12-19T12:13:12.153+0000: 12349.672: [Pause Final MarkTotal Garbage: 4058M
Immediate Garbage: 1164M, 583 regions (31% of total)
Garbage to be collected: 2456M (60% of total), 1294 regions
Live objects to be evacuated: 129M
Live/garbage ratio in collected regions: 5%
 5257M->4095M(6144M), 13.076 ms]
2017-12-19T12:13:12.167+0000: 12349.686: [Concurrent evacuation 4099M->4237M(6144M), 106.069 ms]
2017-12-19T12:13:12.274+0000: 12349.793: [Pause Init Update Refs, 0.104 ms]
2017-12-19T12:13:12.274+0000: 12349.793: [Concurrent update references  4237M->4254M(6144M), 687.437 ms]
2017-12-19T12:13:12.962+0000: 12350.481: [Pause Final Update Refs 4254M->1668M(6144M), 2.407 ms]
2017-12-19T12:13:12.965+0000: 12350.484: [Concurrent reset bitmaps 1668M->1668M(6144M), 3.446 ms]
Capacity: 6144M, Peak Occupancy: 5257M, Lowest Free: 886M, Free Threshold: 184M
Concurrent marking triggered. Free: 1035M, Free Threshold: 1044M; Allocated: 1035M, Alloc Threshold: 0M
2017-12-19T12:14:10.870+0000: 12408.389: [Pause Init Mark, 2.398 ms]
2017-12-19T12:14:10.872+0000: 12408.391: [Concurrent marking 5098M->5293M(6144M), 1229.373 ms]
2017-12-19T12:14:12.102+0000: 12409.622: [Pause Final MarkTotal Garbage: 4061M
Immediate Garbage: 1206M, 603 regions (32% of total)
Garbage to be collected: 2409M (59% of total), 1268 regions
Live objects to be evacuated: 123M
Live/garbage ratio in collected regions: 5%
 5293M->4089M(6144M), 35.800 ms]
2017-12-19T12:14:12.139+0000: 12409.659: [Concurrent evacuation 4098M->4226M(6144M), 100.445 ms]
2017-12-19T12:14:12.241+0000: 12409.760: [Pause Init Update Refs, 0.100 ms]
2017-12-19T12:14:12.241+0000: 12409.760: [Concurrent update references  4226M->4245M(6144M), 697.900 ms]
2017-12-19T12:14:12.940+0000: 12410.459: [Pause Final Update Refs 4245M->1711M(6144M), 2.315 ms]
2017-12-19T12:14:12.942+0000: 12410.461: [Concurrent reset bitmaps 1711M->1711M(6144M), 3.816 ms]
Capacity: 6144M, Peak Occupancy: 5293M, Lowest Free: 850M, Free Threshold: 184M
Adjusting free threshold to: 12% (737M)
Concurrent marking triggered. Free: 736M, Free Threshold: 737M; Allocated: 736M, Alloc Threshold: 0M
2017-12-19T12:14:37.225+0000: 12434.744: [Pause Init Mark, 2.908 ms]
2017-12-19T12:14:37.228+0000: 12434.747: [Concurrent marking 5401M->5851M(6144M), 1192.213 ms]
2017-12-19T12:14:38.420+0000: 12435.939: [Concurrent precleaning 5851M->5851M(6144M), 0.398 ms]
2017-12-19T12:14:38.421+0000: 12435.940: [Pause Final MarkTotal Garbage: 4561M
Immediate Garbage: 2298M, 1149 regions (53% of total)
Garbage to be collected: 1898M (41% of total), 989 regions
Live objects to be evacuated: 77M
Live/garbage ratio in collected regions: 4%
 5851M->3555M(6144M), 16.073 ms]
2017-12-19T12:14:38.437+0000: 12435.957: [Concurrent evacuation 3559M->3685M(6144M), 103.447 ms]
2017-12-19T12:14:38.542+0000: 12436.061: [Pause Init Update Refs, 0.104 ms]
2017-12-19T12:14:38.542+0000: 12436.061: [Concurrent update references  3685M->4019M(6144M), 935.649 ms]
2017-12-19T12:14:39.482+0000: 12437.001: [Pause Final Update Refs 4019M->2043M(6144M), 2.179 ms]
2017-12-19T12:14:39.484+0000: 12437.004: [Concurrent reset bitmaps 2043M->2045M(6144M), 4.248 ms]
Capacity: 6144M, Peak Occupancy: 5851M, Lowest Free: 292M, Free Threshold: 184M
Concurrent marking triggered. Free: 732M, Free Threshold: 737M; Allocated: 732M, Alloc Threshold: 0M
2017-12-19T12:15:10.995+0000: 12468.518: [Pause Init Mark, 6.252 ms]
2017-12-19T12:15:11.002+0000: 12468.521: [Concurrent marking 5408M->5852M(6144M), 1412.717 ms]
2017-12-19T12:15:12.415+0000: 12469.935: [Pause Final MarkTotal Garbage: 4407M
Immediate Garbage: 1828M, 914 regions (45% of total)
Garbage to be collected: 2136M (48% of total), 1113 regions
Live objects to be evacuated: 87M
Live/garbage ratio in collected regions: 4%
 5852M->4026M(6144M), 11.499 ms]
2017-12-19T12:15:12.427+0000: 12469.946: [Concurrent evacuation 4028M->4121M(6144M), 77.189 ms]
2017-12-19T12:15:12.505+0000: 12470.024: [Pause Init Update Refs, 0.104 ms]
2017-12-19T12:15:12.505+0000: 12470.025: [Concurrent update references  4121M->4157M(6144M), 763.012 ms]
2017-12-19T12:15:13.269+0000: 12470.788: [Pause Final Update Refs 4157M->1932M(6144M), 2.305 ms]
2017-12-19T12:15:13.272+0000: 12470.791: [Concurrent reset bitmaps 1932M->1932M(6144M), 3.267 ms]
Capacity: 6144M, Peak Occupancy: 5852M, Lowest Free: 291M, Free Threshold: 184M

--
wbr, Kirill