Long GC pause(promotion failure) in CMS when heap is just half used

[Tao Feng]

Hi,

We encounter a long GC pause in one of our production service and would
like to seek your suggestion on what's happening here.

I understand that heap could be very fragmented which object could
encounter promote failure even the heap still has plenty of space. But in
this case the heap is just about one half usage which I kinda doubt the
heap could be that fragmented...

Any suggetions of how to further debug would be appreciated.

Thanks,
-Tao

///////////JVM flag/////////
CommandLine flags: -XX:+AlwaysPreTouch
-XX:CMSInitiatingOccupancyFraction=85 -XX:ErrorFile=logs/hs_err.log
-XX:GCLogFileSize=26214400 -XX:+HeapDumpOnOutOfMemoryError
-XX:InitialHeapSize=17179869184 -XX:+ManagementServer
-XX:MaxHeapSize=17179869184 -XX:MaxMetaspaceSize=134217728
-XX:MaxNewSize=805306368 -XX:MaxTenuringThreshold=15
-XX:MetaspaceSize=134217728 -XX:MinHeapDeltaBytes=196608
-XX:NewSize=805306368 -XX:NumberOfGCLogFiles=40 -XX:OldPLABSize=16
-XX:OldSize=16374562816 -XX:+ParallelRefProcEnabled -XX:+PrintGC
-XX:+PrintGCApplicationStoppedTime -XX:+PrintGCDateStamps
-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTenuringDistribution
-XX:SurvivorRatio=8 -XX:-UseCompressedOops -XX:+UseConcMarkSweepGC
-XX:+UseGCLogFileRotation -XX:+UseParNewGC


////////////GC Log//////////////
2016-05-09T13:20:43.984+0000: 420349.714: [GC (Allocation Failure)
420349.714: [ParNew
Desired survivor size 40239104 bytes, new threshold 2 (max 15)
- age   1:   26070160 bytes,   26070160 total
- age   2:   15543856 bytes,   41614016 total
- age   3:   10532152 bytes,   52146168 total
: 686280K->57692K(707840K), 0.0375021 secs] 7482403K->6863648K(16698624K),
0.0378490 secs] [Times: user=0.38 sys=0.03, real=0.03 secs]
2016-05-09T13:20:44.022+0000: 420349.753: Total time for which application
threads were stopped: 0.0427562 seconds
2016-05-09T13:20:44.939+0000: 420350.669: [GC (Allocation Failure)
420350.670: [ParNew
Desired survivor size 40239104 bytes, new threshold 15 (max 15)
- age   1:   27280264 bytes,   27280264 total
- age   2:   11179688 bytes,   38459952 total
: 686569K->50544K(707840K), 0.0644130 secs] 7492525K->6881668K(16698624K),
0.0648059 secs] [Times: user=0.50 sys=0.09, real=0.07 secs]
2016-05-09T13:20:45.004+0000: 420350.735: Total time for which application
threads were stopped: 0.0700694 seconds
2016-05-09T13:20:45.653+0000: 420351.383: [GC (Allocation Failure)
420351.383: [ParNew
Desired survivor size 40239104 bytes, new threshold 3 (max 15)
- age   1:   25456392 bytes,   25456392 total
- age   2:   11812240 bytes,   37268632 total
- age   3:   10727648 bytes,   47996280 total
: 679424K->58946K(707840K), 0.0252806 secs] 7510548K->6890070K(16698624K),
0.0256222 secs] [Times: user=0.30 sys=0.01, real=0.02 secs]
2016-05-09T13:20:45.679+0000: 420351.409: Total time for which application
threads were stopped: 0.0302293 seconds
2016-05-09T13:20:46.632+0000: 420352.363: [GC (Allocation Failure)
420352.363: [ParNew (*promotion failed*): 687696K->681421K(707840K),
0.3959862 secs]420352.759: [CMS: *6833071K*->751692K(*15990784K*),
28.4273576 secs] 7518819K->751692K(16698624K), [Metaspace:
73074K->73074K(75776K)], 28.8237795 secs] [Times: user=7.49 sys=4.13, real=
*28.82* secs]
2016-05-09T13:21:15.456+0000: 420381.187: Total time for which application
threads were stopped: *28.8286392* seconds
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20160510/e6b32717/attachment.html>