G1GC remark phase is taking too long

Question

My server application under load some times goes unresponsive and i found the issue to be related to very long "GC Remark". There is no garbage collection tuning implemented. My test server is a 4 core/8 gb/8 GB swap.

This is the log output from gc logs.

2014-04-06T04:39:58.426+0530: 67263.405: [GC remark, 46.7308340 secs]
2014-04-06T04:40:45.167+0530: 67310.146: [GC cleanup 1951M->1750M(2954M), 0.0037930 secs]
2014-04-06T04:40:45.174+0530: 67310.153: [GC concurrent-cleanup-start]
2014-04-06T04:40:45.175+0530: 67310.154: [GC concurrent-cleanup-end, 0.0002800 secs]
2014-04-06T04:40:45.633+0530: 67310.612: [GC pause (young) 2451M->1546M(2954M), 0.0764360 secs]
2014-04-06T04:40:45.815+0530: 67310.794: [GC pause (young) (initial-mark) 1672M->1554M(2954M), 0.0687640 secs]
2014-04-06T04:40:45.884+0530: 67310.863: [GC concurrent-root-region-scan-start]
2014-04-06T04:40:45.912+0530: 67310.891: [GC concurrent-root-region-scan-end, 0.0285320 secs]
2014-04-06T04:40:45.912+0530: 67310.891: [GC concurrent-mark-start]
2014-04-06T04:40:46.919+0530: 67311.898: [GC pause (young) 2590M->1622M(2954M), 0.0752180 secs]
2014-04-06T04:40:47.231+0530: 67312.210: [GC concurrent-mark-end, 1.3191870 secs]
2014-04-06T04:40:47.239+0530: 67312.218: [GC remark, 46.6353020 secs]

In this state, i tried turn off swap, but that doesnt seems to help reduce the remark time. There is another test server which runs 4 gb memory and there things are better and stable.

Any thoughts on how i can improve this situation.

====== EDIT - Adding logs from -XX:+PrintGCDetails =========

2014-04-06T09:45:30.953+0530: 7777.585: [GC remark 2014-04-06T09:45:30.959+0530: 7777.590: [GC ref-proc, 24.9282110 secs], 24.9556400 secs]
 [Times: user=24.89 sys=0.06, real=24.96 secs]
2014-04-06T09:45:55.921+0530: 7802.553: [GC cleanup 2053M->1822M(2954M), 0.0039070 secs]
 [Times: user=0.01 sys=0.00, real=0.01 secs]
2014-04-06T09:45:55.928+0530: 7802.560: [GC concurrent-cleanup-start]
2014-04-06T09:45:55.929+0530: 7802.560: [GC concurrent-cleanup-end, 0.0003390 secs]
2014-04-06T09:45:56.254+0530: 7802.885: [GC pause (young), 0.0770030 secs]
   [Parallel Time: 70.3 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 7802888.9, Avg: 7802889.0, Max: 7802889.0, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 22.2, Avg: 24.2, Max: 26.5, Diff: 4.2, Sum: 96.7]
      [Update RS (ms): Min: 13.8, Avg: 15.9, Max: 18.2, Diff: 4.4, Sum: 63.7]
         [Processed Buffers: Min: 177, Avg: 183.2, Max: 189, Diff: 12, Sum: 733]
      [Scan RS (ms): Min: 0.2, Avg: 0.3, Max: 0.3, Diff: 0.1, Sum: 1.2]
      [Object Copy (ms): Min: 29.2, Avg: 29.6, Max: 30.4, Diff: 1.2, Sum: 118.4]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3]
      [GC Worker Total (ms): Min: 70.0, Avg: 70.1, Max: 70.2, Diff: 0.1, Sum: 280.5]
      [GC Worker End (ms): Min: 7802959.0, Avg: 7802959.1, Max: 7802959.1, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 6.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.4 ms]
      [Ref Enq: 0.0 ms]
      [Free CSet: 1.1 ms]
   [Eden: 766.0M(766.0M)->0.0B(101.0M) Survivors: 28.0M->46.0M Heap: 2359.1M(2954.0M)->1610.6M(2954.0M)]
 [Times: user=0.29 sys=0.00, real=0.07 secs]
2014-04-06T09:45:56.434+0530: 7803.066: [GC pause (mixed), 0.0560090 secs]
   [Parallel Time: 50.4 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 7803069.3, Avg: 7803069.3, Max: 7803069.4, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 20.9, Avg: 23.2, Max: 26.1, Diff: 5.3, Sum: 92.6]
      [Update RS (ms): Min: 1.4, Avg: 4.0, Max: 6.6, Diff: 5.2, Sum: 16.1]
         [Processed Buffers: Min: 29, Avg: 38.0, Max: 49, Diff: 20, Sum: 152]
      [Scan RS (ms): Min: 0.2, Avg: 0.2, Max: 0.3, Diff: 0.0, Sum: 0.9]
      [Object Copy (ms): Min: 22.4, Avg: 22.8, Max: 23.6, Diff: 1.1, Sum: 91.2]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.2]
      [GC Worker Total (ms): Min: 50.2, Avg: 50.3, Max: 50.3, Diff: 0.1, Sum: 201.0]
      [GC Worker End (ms): Min: 7803119.6, Avg: 7803119.6, Max: 7803119.6, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 5.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.1 ms]
      [Ref Enq: 0.0 ms]
      [Free CSet: 0.4 ms]
   [Eden: 101.0M(101.0M)->0.0B(934.0M) Survivors: 46.0M->5120.0K Heap: 1727.6M(2954.0M)->1608.3M(2954.0M)]
 [Times: user=0.20 sys=0.00, real=0.05 secs]
2014-04-06T09:45:56.612+0530: 7803.244: [GC pause (young) (initial-mark), 0.0612000 secs]
   [Parallel Time: 54.2 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 7803247.0, Avg: 7803248.2, Max: 7803252.0, Diff: 5.0]
      [Ext Root Scanning (ms): Min: 19.9, Avg: 24.1, Max: 28.7, Diff: 8.8, Sum: 96.3]
      [Update RS (ms): Min: 12.4, Avg: 15.0, Max: 17.4, Diff: 5.1, Sum: 60.2]
         [Processed Buffers: Min: 48, Avg: 63.8, Max: 79, Diff: 31, Sum: 255]
      [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.2]
      [Object Copy (ms): Min: 12.3, Avg: 13.5, Max: 16.6, Diff: 4.2, Sum: 54.2]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.2]
      [GC Worker Total (ms): Min: 49.1, Avg: 52.8, Max: 54.0, Diff: 5.0, Sum: 211.1]
      [GC Worker End (ms): Min: 7803301.0, Avg: 7803301.0, Max: 7803301.1, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 6.8 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.0 ms]
      [Ref Enq: 0.0 ms]
      [Free CSet: 0.4 ms]
   [Eden: 134.0M(934.0M)->0.0B(927.0M) Survivors: 5120.0K->16.0M Heap: 1741.7M(2954.0M)->1618.8M(2954.0M)]
 [Times: user=0.22 sys=0.00, real=0.07 secs]
2014-04-06T09:45:56.675+0530: 7803.306: [GC concurrent-root-region-scan-start]
2014-04-06T09:45:56.685+0530: 7803.316: [GC concurrent-root-region-scan-end, 0.0100810 secs]
2014-04-06T09:45:56.685+0530: 7803.316: [GC concurrent-mark-start]
2014-04-06T09:45:57.759+0530: 7804.391: [GC pause (young), 0.0648020 secs]
   [Parallel Time: 55.0 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 7804393.8, Avg: 7804393.9, Max: 7804393.9, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 21.4, Avg: 23.8, Max: 26.5, Diff: 5.1, Sum: 95.0]
      [SATB Filtering (ms): Min: 0.0, Avg: 0.4, Max: 1.7, Diff: 1.7, Sum: 1.7]
      [Update RS (ms): Min: 13.3, Avg: 15.4, Max: 18.3, Diff: 5.0, Sum: 61.7]
         [Processed Buffers: Min: 110, Avg: 165.8, Max: 224, Diff: 114, Sum: 663]
      [Scan RS (ms): Min: 0.3, Avg: 0.4, Max: 0.4, Diff: 0.0, Sum: 1.4]
      [Object Copy (ms): Min: 14.4, Avg: 14.8, Max: 15.5, Diff: 1.1, Sum: 59.1]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3]
      [GC Worker Total (ms): Min: 54.7, Avg: 54.8, Max: 54.9, Diff: 0.1, Sum: 219.3]
      [GC Worker End (ms): Min: 7804448.7, Avg: 7804448.7, Max: 7804448.7, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Clear CT: 0.3 ms]
   [Other: 9.6 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 4.5 ms]
      [Ref Enq: 0.0 ms]
      [Free CSet: 1.2 ms]
   [Eden: 916.0M(927.0M)->0.0B(853.0M) Survivors: 16.0M->25.0M Heap: 2592.4M(2954.0M)->1685.9M(2954.0M)]
 [Times: user=0.24 sys=0.00, real=0.07 secs]
2014-04-06T09:45:58.330+0530: 7804.961: [GC concurrent-mark-end, 1.6449220 secs]
2014-04-06T09:45:58.335+0530: 7804.967: [GC remark 2014-04-06T09:45:58.339+0530: 7804.970: [GC ref-proc, 26.3976280 secs], 26.4233450 secs]
 [Times: user=26.28 sys=0.14, real=26.42 secs]

==== Edit After adding -XX:+PrintReferenceGC and -XX:+ParallelRefProcEnabled ======

[GC remark : 
    [GC ref-proc: 
        [SoftReference, 122658 refs, 11.4784560 secs]
        [WeakReference, 714 refs, 0.1420020 secs]
        [FinalReference, 32 refs, 0.0145060 secs]
        [PhantomReference, 37 refs, 0.0144000 secs]
        [JNI Weak Reference, 1.2714530 secs]
    , 12.9211700 secs]
, 12.9469960 secs]

Now softreference is taking most of the time. I have found a code section which creates a large number of softreferences per second. I will disable that and see if it helps.

========== EDIT - After Removing softreference from code ==========

After removing soft references by fixing code, things have vastly improved and SoftRefernece processing time is negligible now !!! . One last problem i still see "JNI Weak Reference" time gradually increasing. I will investigate that issue now.

Answer 1

I'm not sure if this is a red-herring, but according to this article the remark phase also does reference processing. So if your application is using huge numbers of soft/weak references, it could inflate the remark phase.

If you add Option -XX:+PrintGCDetails you might get more info in the GC log ...