title: G1GC remark phase is taking too long
body: <p>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.</p>
  
  <p>This is the log output from gc logs.</p>
  
  <pre><code>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-&gt;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-&gt;1546M(2954M), 0.0764360 secs]
  2014-04-06T04:40:45.815+0530: 67310.794: [GC pause (young) (initial-mark) 1672M-&gt;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-&gt;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]
  </code></pre>
  
  <p>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. </p>
  
  <p>Any thoughts on how i can improve this situation.</p>
  
  <p>====== EDIT - Adding logs from -XX:+PrintGCDetails =========</p>
  
  <pre><code>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-&gt;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)-&gt;0.0B(101.0M) Survivors: 28.0M-&gt;46.0M Heap: 2359.1M(2954.0M)-&gt;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)-&gt;0.0B(934.0M) Survivors: 46.0M-&gt;5120.0K Heap: 1727.6M(2954.0M)-&gt;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)-&gt;0.0B(927.0M) Survivors: 5120.0K-&gt;16.0M Heap: 1741.7M(2954.0M)-&gt;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)-&gt;0.0B(853.0M) Survivors: 16.0M-&gt;25.0M Heap: 2592.4M(2954.0M)-&gt;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]
  </code></pre>
  
  <p>==== Edit After adding -XX:+PrintReferenceGC  and -XX:+ParallelRefProcEnabled  ======</p>
  
  <pre><code>[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]
  </code></pre>
  
  <p>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. </p>
  
  <p>==========  EDIT - After Removing softreference from code ==========</p>
  
  <p>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.</p>