Object Copy and Termination times leading to long pauses

[Srini Padman]

Hello,

We are seeing occasionally long young GC pauses, in the order of 20-25 seconds, in our application. When this happens, the pause generally occurs a few hours after the JVM starts. I am extracting the G1 GC settings and GC logs below.
The bulk of the time in these pauses seems to be associated with "Object Copy" and "Termination" phases - and I am not sure what to do about these. Any help you can offer will be greatly appreciated!

JVM settings:
--------------

-server -Xms4096m -Xmx4096m -Xss512k -XX:PermSize=128m  -XX:MaxPermSize=128m -XX:+UseG1GC -XX:G1HeapRegionSize=2m -XX:G1MixedGCLiveThresholdPercent=75 -XX:G1HeapWastePercent=5 -XX:InitiatingHeapOccupancyPercent=65 -XX:+ParallelRefProcEnabled -XX:+DisableExplicitGC -XX:+UnlockDiagnosticVMOptions -XX:+UnlockExperimentalVMOptions -XX:+ForceTimeHighResolution 

For the sake of completeness, I should add that we also have the following (logging) options:

-verbose:gc  -XX:+PrintAdaptiveSizePolicy -XX:+PrintGCDetails -XX:+PrintGCTimeStamps   -XX:+PrintGCDateStamps -XX:-PrintTenuringDistribution -XX:+PrintPromotionFailure -XX:+G1PrintRegionLivenessInfo

GC log snippet (full file attached):
-------------------------------------

2015-07-22T21:02:54.488-0700: 47912.944: [GC pause (young) 47913.463: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 50724, predicted base time: 64.43 ms, remaining time: 135.57 ms, target pause time: 200.00 ms]
 47913.463: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 1178 regions, survivors: 50 regions, predicted young region time: 28.63 ms]
 47913.463: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 1178 regions, survivors: 50 regions, old: 0 regions, predicted pause time: 93.06 ms, target pause time: 200.00 ms]
, 24.2055085 secs]
   [Parallel Time: 22056.7 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 47913627.1, Avg: 47913687.6, Max: 47913745.7, Diff: 118.6]
      [Ext Root Scanning (ms): Min: 652.7, Avg: 804.7, Max: 913.9, Diff: 261.2, Sum: 6437.8]
      [Update RS (ms): Min: 1396.7, Avg: 1446.8, Max: 1496.6, Diff: 99.9, Sum: 11574.4]
         [Processed Buffers: Min: 13, Avg: 37.3, Max: 60, Diff: 47, Sum: 298]
      [Scan RS (ms): Min: 0.1, Avg: 22.2, Max: 44.3, Diff: 44.2, Sum: 177.3]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.7, Max: 3.9, Diff: 3.9, Sum: 5.5]
      [Object Copy (ms): Min: 5649.2, Avg: 6518.0, Max: 6904.2, Diff: 1255.0, Sum: 52144.2]
      [Termination (ms): Min: 12811.8, Avg: 13175.9, Max: 14032.8, Diff: 1221.0, Sum: 105406.8]
      [GC Worker Other (ms): Min: 0.1, Avg: 5.7, Max: 23.4, Diff: 23.3, Sum: 45.3]
      [GC Worker Total (ms): Min: 21915.9, Avg: 21973.9, Max: 22034.4, Diff: 118.5, Sum: 175791.3]
      [GC Worker End (ms): Min: 47935661.5, Avg: 47935661.6, Max: 47935661.6, Diff: 0.2]
   [Code Root Fixup: 0.2 ms]
   [Code Root Migration: 0.5 ms]
   [Clear CT: 227.8 ms]
   [Other: 1920.3 ms]
      [Choose CSet: 0.1 ms]
      [Ref Proc: 646.0 ms]
      [Ref Enq: 2.6 ms]
      [Free CSet: 539.4 ms]
   [Eden: 2356.0M(2356.0M)->0.0B(100.0M) Survivors: 100.0M->104.0M Heap: 3495.9M(4096.0M)->1150.8M(4096.0M)]
 [Times: user=103.32 sys=1.59, real=24.26 secs] 
 
 Regards,
 Srini.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20150728/498fe1c9/attachment-0001.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: gc-20150722_074417.zip
Type: application/zip
Size: 86418 bytes
Desc: not available
URL: <http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20150728/498fe1c9/gc-20150722_074417-0001.zip>