<div dir="ltr">Thanks for the response. Here are the additional logs.<div><br></div><div><blockquote style="margin:0px 0px 0px 40px;border:none;padding:0px"><div><div>0.094: [GC pause (young), 0.0347877 secs]</div></div><div>
<div> [Parallel Time: 34.1 ms, GC Workers: 8]</div></div><div><div> [GC Worker Start (ms): Min: 94.2, Avg: 104.4, Max: 126.4, Diff: 32.2]</div></div><div><div> [Ext Root Scanning (ms): Min: 0.0, Avg: 3.3, Max: 25.0, Diff: 25.0, Sum: 26.6]</div>
</div><div><div> [Update RS (ms): Min: 0.0, Avg: 2.1, Max: 5.3, Diff: 5.3, Sum: 16.7]</div></div><div><div> [Processed Buffers: Min: 0, Avg: 2.3, Max: 9, Diff: 9, Sum: 18]</div></div><div><div> [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]</div>
</div><div><div> [Object Copy (ms): Min: 1.8, Avg: 18.3, Max: 29.9, Diff: 28.2, Sum: 146.4]</div></div><div><div> [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.6]</div></div><div><div> [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]</div>
</div><div><div> [GC Worker Total (ms): Min: 1.9, Avg: 23.8, Max: 34.1, Diff: 32.2, Sum: 190.4]</div></div><div><div> [GC Worker End (ms): Min: 128.2, Avg: 128.3, Max: 128.3, Diff: 0.0]</div></div><div><div> [Code Root Fixup: 0.0 ms]</div>
</div><div><div> [Clear CT: 0.0 ms]</div></div><div><div> [Other: 0.6 ms]</div></div><div><div> [Choose CSet: 0.0 ms]</div></div><div><div> [Ref Proc: 0.3 ms]</div></div><div><div> [Ref Enq: 0.0 ms]</div>
</div><div><div> [Free CSet: 0.0 ms]</div></div><div><div> [Eden: 24.0M(24.0M)->0.0B(11.0M) Survivors: 0.0B->3072.0K Heap: 62.1M(254.0M)->62.2M(254.0M)]</div></div><div><div> [Times: user=0.09 sys=0.03, real=0.04 secs] </div>
</div><div><div>0.131: [GC pause (young), 0.0295093 secs]</div></div><div><div> [Parallel Time: 28.1 ms, GC Workers: 8]</div></div><div><div> [GC Worker Start (ms): Min: 130.9, Avg: 135.5, Max: 158.7, Diff: 27.8]</div>
</div><div><div> [Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.4, Sum: 1.2]</div></div><div><div> [Update RS (ms): Min: 0.0, Avg: 11.4, Max: 27.5, Diff: 27.5, Sum: 90.8]</div></div><div><div> [Processed Buffers: Min: 0, Avg: 23.8, Max: 42, Diff: 42, Sum: 190]</div>
</div><div><div> [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]</div></div><div><div> [Object Copy (ms): Min: 0.0, Avg: 11.7, Max: 17.1, Diff: 17.1, Sum: 93.8]</div></div><div><div> [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 1.7]</div>
</div><div><div> [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]</div></div><div><div> [GC Worker Total (ms): Min: 0.2, Avg: 23.5, Max: 28.1, Diff: 27.8, Sum: 187.7]</div></div><div><div>
[GC Worker End (ms): Min: 159.0, Avg: 159.0, Max: 159.0, Diff: 0.0]</div></div><div><div> [Code Root Fixup: 0.0 ms]</div></div><div><div> [Clear CT: 0.1 ms]</div></div><div><div> [Other: 1.3 ms]</div></div><div>
<div> [Choose CSet: 0.0 ms]</div></div><div><div> [Ref Proc: 0.1 ms]</div></div><div><div> [Ref Enq: 0.0 ms]</div></div><div><div> [Free CSet: 0.0 ms]</div></div><div><div> [Eden: 11.0M(11.0M)->0.0B(23.0M) Survivors: 3072.0K->2048.0K Heap: 73.2M(254.0M)->82.7M(508.0M)]</div>
</div><div><div> [Times: user=0.19 sys=0.00, real=0.03 secs] </div></div><div><div>0.166: [GC pause (young), 0.0385523 secs]</div></div><div><div> [Parallel Time: 35.9 ms, GC Workers: 8]</div></div><div><div> [GC Worker Start (ms): Min: 166.4, Avg: 169.8, Max: 192.4, Diff: 25.9]</div>
</div><div><div> [Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.4, Sum: 1.9]</div></div><div><div> [Update RS (ms): Min: 0.0, Avg: 10.9, Max: 31.9, Diff: 31.9, Sum: 87.2]</div></div><div><div> [Processed Buffers: Min: 0, Avg: 14.6, Max: 26, Diff: 26, Sum: 117]</div>
</div><div><div> [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]</div></div><div><div> [Object Copy (ms): Min: 3.5, Avg: 21.4, Max: 27.0, Diff: 23.4, Sum: 171.1]</div></div><div><div> [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.4]</div>
</div><div><div> [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]</div></div><div><div> [GC Worker Total (ms): Min: 10.0, Avg: 32.6, Max: 35.9, Diff: 25.9, Sum: 260.7]</div></div><div><div>
[GC Worker End (ms): Min: 202.3, Avg: 202.4, Max: 202.4, Diff: 0.0]</div></div><div><div> [Code Root Fixup: 0.0 ms]</div></div><div><div> [Clear CT: 0.0 ms]</div></div><div><div> [Other: 2.6 ms]</div></div><div>
<div> [Choose CSet: 0.0 ms]</div></div><div><div> [Ref Proc: 0.1 ms]</div></div><div><div> [Ref Enq: 0.0 ms]</div></div><div><div> [Free CSet: 0.0 ms]</div></div><div><div> [Eden: 23.0M(23.0M)->0.0B(46.0M) Survivors: 2048.0K->4096.0K Heap: 105.7M(508.0M)->110.1M(1016.0M)]</div>
</div><div><div> [Times: user=0.19 sys=0.00, real=0.04 secs] </div></div><div><div>0.222: [GC pause (young), 0.0558720 secs]</div></div><div><div> [Parallel Time: 53.0 ms, GC Workers: 8]</div></div><div><div> [GC Worker Start (ms): Min: 222.0, Avg: 222.2, Max: 222.5, Diff: 0.5]</div>
</div><div><div> [Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.4, Sum: 1.5]</div></div><div><div> [Update RS (ms): Min: 7.7, Avg: 8.7, Max: 10.9, Diff: 3.2, Sum: 69.4]</div></div><div><div> [Processed Buffers: Min: 7, Avg: 8.5, Max: 12, Diff: 5, Sum: 68]</div>
</div><div><div> [Scan RS (ms): Min: 0.0, Avg: 0.3, Max: 0.6, Diff: 0.6, Sum: 2.3]</div></div><div><div> [Object Copy (ms): Min: 41.7, Avg: 43.6, Max: 44.3, Diff: 2.7, Sum: 348.5]</div></div><div><div> [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]</div>
</div><div><div> [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]</div></div><div><div> [GC Worker Total (ms): Min: 52.4, Avg: 52.7, Max: 52.9, Diff: 0.5, Sum: 421.8]</div></div><div><div>
[GC Worker End (ms): Min: 274.9, Avg: 274.9, Max: 274.9, Diff: 0.0]</div></div><div><div> [Code Root Fixup: 0.0 ms]</div></div><div><div> [Clear CT: 0.0 ms]</div></div><div><div> [Other: 2.8 ms]</div></div><div>
<div> [Choose CSet: 0.0 ms]</div></div><div><div> [Ref Proc: 0.1 ms]</div></div><div><div> [Ref Enq: 0.0 ms]</div></div><div><div> [Free CSet: 0.0 ms]</div></div><div><div> [Eden: 46.0M(46.0M)->0.0B(74.0M) Survivors: 4096.0K->7168.0K Heap: 156.1M(1016.0M)->158.6M(1625.0M)]</div>
</div><div><div> [Times: user=0.48 sys=0.01, real=0.06 secs] </div></div><div><div>0.328: [GC pause (young), 0.0853794 secs]</div></div><div><div> [Parallel Time: 82.8 ms, GC Workers: 8]</div></div><div><div> [GC Worker Start (ms): Min: 327.9, Avg: 330.8, Max: 351.1, Diff: 23.2]</div>
</div><div><div> [Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 2.0]</div></div><div><div> [Update RS (ms): Min: 0.0, Avg: 5.5, Max: 8.3, Diff: 8.3, Sum: 43.9]</div></div><div><div> [Processed Buffers: Min: 0, Avg: 2.3, Max: 3, Diff: 3, Sum: 18]</div>
</div><div><div> [Scan RS (ms): Min: 0.0, Avg: 2.2, Max: 3.3, Diff: 3.3, Sum: 17.4]</div></div><div><div> [Object Copy (ms): Min: 59.5, Avg: 71.8, Max: 73.7, Diff: 14.2, Sum: 574.7]</div></div><div><div> [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]</div>
</div><div><div> [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]</div></div><div><div> [GC Worker Total (ms): Min: 59.5, Avg: 79.8, Max: 82.7, Diff: 23.2, Sum: 638.4]</div></div><div><div>
[GC Worker End (ms): Min: 410.6, Avg: 410.7, Max: 410.7, Diff: 0.0]</div></div><div><div> [Code Root Fixup: 0.0 ms]</div></div><div><div> [Clear CT: 0.1 ms]</div></div><div><div> [Other: 2.6 ms]</div></div><div>
<div> [Choose CSet: 0.0 ms]</div></div><div><div> [Ref Proc: 0.1 ms]</div></div><div><div> [Ref Enq: 0.0 ms]</div></div><div><div> [Free CSet: 0.1 ms]</div></div><div><div> [Eden: 74.0M(74.0M)->0.0B(94.0M) Survivors: 7168.0K->11.0M Heap: 232.6M(1625.0M)->237.6M(2112.0M)]</div>
</div><div><div> [Times: user=0.59 sys=0.00, real=0.09 secs] </div></div><div><div>0.447: [GC pause (young), 0.1239103 secs]</div></div><div><div> [Parallel Time: 121.5 ms, GC Workers: 8]</div></div><div><div> [GC Worker Start (ms): Min: 447.5, Avg: 447.7, Max: 448.5, Diff: 0.9]</div>
</div><div><div> [Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 1.9]</div></div><div><div> [Update RS (ms): Min: 26.5, Avg: 28.2, Max: 28.7, Diff: 2.2, Sum: 225.7]</div></div><div><div> [Processed Buffers: Min: 38, Avg: 39.8, Max: 44, Diff: 6, Sum: 318]</div>
</div><div><div> [Scan RS (ms): Min: 0.3, Avg: 0.7, Max: 1.9, Diff: 1.6, Sum: 5.3]</div></div><div><div> [Object Copy (ms): Min: 92.1, Avg: 92.2, Max: 92.3, Diff: 0.2, Sum: 737.5]</div></div><div><div> [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3]</div>
</div><div><div> [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]</div></div><div><div> [GC Worker Total (ms): Min: 120.6, Avg: 121.4, Max: 121.5, Diff: 0.9, Sum: 970.8]</div></div><div>
<div> [GC Worker End (ms): Min: 569.0, Avg: 569.0, Max: 569.0, Diff: 0.0]</div></div><div><div> [Code Root Fixup: 0.0 ms]</div></div><div><div> [Clear CT: 0.1 ms]</div></div><div><div> [Other: 2.3 ms]</div></div>
<div><div> [Choose CSet: 0.0 ms]</div></div><div><div> [Ref Proc: 0.1 ms]</div></div><div><div> [Ref Enq: 0.0 ms]</div></div><div><div> [Free CSet: 0.1 ms]</div></div><div><div> [Eden: 94.0M(94.0M)->0.0B(111.0M) Survivors: 11.0M->14.0M Heap: 331.6M(2112.0M)->334.6M(2502.0M)]</div>
</div><div><div> [Times: user=0.80 sys=0.05, real=0.12 secs] </div></div><div><div>0.599: [GC pause (young), 0.1479438 secs]</div></div><div><div> [Parallel Time: 145.7 ms, GC Workers: 8]</div></div><div><div> [GC Worker Start (ms): Min: 599.4, Avg: 599.5, Max: 599.8, Diff: 0.4]</div>
</div><div><div> [Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 1.9]</div></div><div><div> [Update RS (ms): Min: 41.8, Avg: 43.0, Max: 44.0, Diff: 2.1, Sum: 343.6]</div></div><div><div> [Processed Buffers: Min: 67, Avg: 70.9, Max: 73, Diff: 6, Sum: 567]</div>
</div><div><div> [Scan RS (ms): Min: 0.0, Avg: 0.8, Max: 1.9, Diff: 1.9, Sum: 6.2]</div></div><div><div> [Object Copy (ms): Min: 101.3, Avg: 101.6, Max: 101.7, Diff: 0.3, Sum: 812.6]</div></div><div><div> [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]</div>
</div><div><div> [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]</div></div><div><div> [GC Worker Total (ms): Min: 145.2, Avg: 145.6, Max: 145.6, Diff: 0.4, Sum: 1164.6]</div></div><div>
<div> [GC Worker End (ms): Min: 745.1, Avg: 745.1, Max: 745.1, Diff: 0.0]</div></div><div><div> [Code Root Fixup: 0.0 ms]</div></div><div><div> [Clear CT: 0.1 ms]</div></div><div><div> [Other: 2.2 ms]</div></div>
<div><div> [Choose CSet: 0.0 ms]</div></div><div><div> [Ref Proc: 0.1 ms]</div></div><div><div> [Ref Enq: 0.0 ms]</div></div><div><div> [Free CSet: 0.1 ms]</div></div><div><div> [Eden: 111.0M(111.0M)->0.0B(124.0M) Survivors: 14.0M->16.0M Heap: 445.6M(2502.0M)->448.6M(2814.0M)]</div>
</div><div><div> [Times: user=1.20 sys=0.05, real=0.15 secs] </div></div><div><div>0.787: [GC pause (young), 0.1625321 secs]</div></div><div><div> [Parallel Time: 160.0 ms, GC Workers: 8]</div></div><div><div> [GC Worker Start (ms): Min: 786.6, Avg: 786.7, Max: 786.9, Diff: 0.4]</div>
</div><div><div> [Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 1.8]</div></div><div><div> [Update RS (ms): Min: 46.4, Avg: 47.0, Max: 49.0, Diff: 2.5, Sum: 376.0]</div></div><div><div> [Processed Buffers: Min: 75, Avg: 78.0, Max: 79, Diff: 4, Sum: 624]</div>
</div><div><div> [Scan RS (ms): Min: 0.0, Avg: 0.9, Max: 1.5, Diff: 1.5, Sum: 7.4]</div></div><div><div> [Object Copy (ms): Min: 110.6, Avg: 111.7, Max: 112.0, Diff: 1.4, Sum: 893.5]</div></div><div><div> [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]</div>
</div><div><div> [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3]</div></div><div><div> [GC Worker Total (ms): Min: 159.6, Avg: 159.9, Max: 160.0, Diff: 0.4, Sum: 1279.0]</div></div><div>
<div> [GC Worker End (ms): Min: 946.5, Avg: 946.5, Max: 946.6, Diff: 0.1]</div></div><div><div> [Code Root Fixup: 0.0 ms]</div></div><div><div> [Clear CT: 0.1 ms]</div></div><div><div> [Other: 2.4 ms]</div></div>
<div><div> [Choose CSet: 0.0 ms]</div></div><div><div> [Ref Proc: 0.1 ms]</div></div><div><div> [Ref Enq: 0.0 ms]</div></div><div><div> [Free CSet: 0.2 ms]</div></div><div><div> [Eden: 124.0M(124.0M)->0.0B(135.0M) Survivors: 16.0M->18.0M Heap: 572.6M(2814.0M)->576.6M(3064.0M)]</div>
</div><div><div> [Times: user=1.37 sys=0.00, real=0.16 secs] </div></div><div><div>0.981: [GC pause (young), 0.2063055 secs]</div></div><div><div> [Parallel Time: 204.1 ms, GC Workers: 8]</div></div><div><div> [GC Worker Start (ms): Min: 980.8, Avg: 980.9, Max: 981.0, Diff: 0.2]</div>
</div><div><div> [Ext Root Scanning (ms): Min: 0.1, Avg: 0.3, Max: 0.3, Diff: 0.2, Sum: 2.1]</div></div><div><div> [Update RS (ms): Min: 55.9, Avg: 57.8, Max: 58.8, Diff: 2.9, Sum: 462.8]</div></div><div><div> [Processed Buffers: Min: 100, Avg: 101.5, Max: 103, Diff: 3, Sum: 812]</div>
</div><div><div> [Scan RS (ms): Min: 0.0, Avg: 1.0, Max: 3.1, Diff: 3.1, Sum: 8.3]</div></div><div><div> [Object Copy (ms): Min: 144.7, Avg: 144.8, Max: 144.9, Diff: 0.1, Sum: 1158.3]</div></div><div><div> [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3]</div>
</div><div><div> [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]</div></div><div><div> [GC Worker Total (ms): Min: 203.8, Avg: 204.0, Max: 204.0, Diff: 0.2, Sum: 1631.9]</div></div><div>
<div> [GC Worker End (ms): Min: 1184.9, Avg: 1184.9, Max: 1184.9, Diff: 0.0]</div></div><div><div> [Code Root Fixup: 0.0 ms]</div></div><div><div> [Clear CT: 0.1 ms]</div></div><div><div> [Other: 2.1 ms]</div></div>
<div><div> [Choose CSet: 0.0 ms]</div></div><div><div> [Ref Proc: 0.1 ms]</div></div><div><div> [Ref Enq: 0.0 ms]</div></div><div><div> [Free CSet: 0.1 ms]</div></div><div><div> [Eden: 135.0M(135.0M)->0.0B(143.0M) Survivors: 18.0M->20.0M Heap: 711.6M(3064.0M)->714.6M(3264.0M)]</div>
</div><div><div> [Times: user=1.40 sys=0.11, real=0.21 secs] </div></div><div><div>CPU Load Is -1.0</div></div><div><div><br></div></div><div><div>Start</div></div><div><div>Stop</div></div><div><div>Sleep</div></div><div>
<div>CPU Load Is 0.9166222455142531</div></div><div><div><br></div></div><div><div>Start</div></div><div><div>Stop</div></div><div><div>Sleep</div></div><div><div>CPU Load Is 0.907013989900451</div></div><div><div><br></div>
</div><div><div>Start</div></div><div><div>Stop</div></div><div><div>Sleep</div></div><div><div>CPU Load Is 0.9085635227776081</div></div><div><div><br></div></div><div><div>Start</div></div><div><div>Stop</div></div><div>
<div>Sleep</div></div><div><div>CPU Load Is 0.909945506396622</div></div></blockquote><div><div><br></div><div><br></div></div><div>Note that all the logged GC occurs during the construction of my graph of Nodes, which is <i>before</i> my algorithm (modifyGraph) starts, There is no log of GC activity once the algorithm starts, but there is significant (100%) CPU usage.<br>
</div></div><div><br></div><div>My questions are:</div><div><ul><li>Why is the G1 garbage collector consuming so much CPU time? What is it doing?</li><li>Why is the G1 garbage collector not logging anything? The only reason I even know it's the garbage collector consuming my CPU time is that (a) I only see this behaviour when the G1 collector is enabled and (b) the load on the CPU correlates with the value of -XX:ParallelGCThreads.</li>
<li>Are there particular object-graph structures that the G1 garbage collector will struggle with? Should complex graphs be considered bad coding practice?<br></li><li>How can I write my code to avoid this behaviour in the G1 garbage collector? For example, if all my Nodes are in an array, will this fix it?</li>
<li>Should this be considered a bug in the G1 garbage collector? This is far beyond 'a small increase in CPU usage'.</li></ul><div>Just to demonstrate the issue further, I timed my calls to modifyGraph() and trialled different GC parameters:</div>
</div><div><ul><li>-XX:+UseG1GC -XX:ParallelGCThreads=1 took 82.393 seconds and CPU load was 0.1247</li><li>-XX:+UseG1GC -XX:ParallelGCThreads=4 took 19.829 seconds and CPU load was 0.5960</li><li>-XX:+UseG1GC -XX:ParallelGCThreads=8 took 14.815 seconds and CPU load was 0.9184<br>
</li><li>-XX:+UseConcMarkSweepGC took 0.322 seconds and CPU load was 0.1119 regardless of the setting of -XX:ParallelGCThreads</li></ul></div><div>So using the CMS GC made my application 44x faster (14.815 seconds versus 0.322 seconds) and placed 1/8th of the load (0.9184 versus 0.1119) on the CPU.</div>
<div><br></div><div>If my code represents some kind of hypothetical worst case for the G1 garbage collector, I think it should be documented and/or fixed somehow.</div><div><br></div><div>Regards,</div><div>Peter.</div><div>
<br></div></div><div class="gmail_extra"><br><br><div class="gmail_quote">On Tue, Jun 3, 2014 at 3:16 PM, Tao Mao <span dir="ltr"><<a href="mailto:yiyeguhu@gmail.com" target="_blank">yiyeguhu@gmail.com</a>></span> wrote:<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">And, use –XX:+PrintGCDetails –XX:+PrintGCTimeStamps to get more log. Thanks. -Tao</div><div class="HOEnZb">
<div class="h5"><div class="gmail_extra"><br><br><div class="gmail_quote">On Tue, Jun 3, 2014 at 2:13 PM, Tao Mao <span dir="ltr"><<a href="mailto:yiyeguhu@gmail.com" target="_blank">yiyeguhu@gmail.com</a>></span> wrote:<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">Hi Peter,<div><br></div><div>What was your actual question? Try -XX:ParallelGCThreads=<value> if you want less CPU usage from GC.</div>
<div><br></div><div>Thanks.</div><span><font color="#888888"><div>Tao</div></font></span></div><div><div><div class="gmail_extra">
<br><br><div class="gmail_quote">On Tue, Jun 3, 2014 at 11:49 AM, Peter Harvey <span dir="ltr"><<a href="mailto:harvey@actenum.com" target="_blank">harvey@actenum.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
<div dir="ltr">Small correction. The last example of output was with "-XX:+UseConcMarkSweepGC -verbose:gc".</div><div><div><div class="gmail_extra"><br><br><div class="gmail_quote">On Tue, Jun 3, 2014 at 12:41 PM, Peter Harvey <span dir="ltr"><<a href="mailto:harvey@actenum.com" target="_blank">harvey@actenum.com</a>></span> wrote:<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">I have an algorithm (at bottom of email) which builds a graph of 'Node' objects with random connections between them. It then repeatedly processes a queue of those Nodes, adding new Nodes to the queue as it goes. This is a single-threaded algorithm that will never terminate. Our actual production code is much more complex, but I've trimmed it down as much as possible.<div>
<br></div><div>On Windows 7 with JRE 7u60, enabling the G1 garbage collector will cause the JRE to consume all 8 cores of my CPU. No other garbage collector does this. You can see the differences in CPU load in the example output below. It's also worth nothing that "-verbose:gc" with the G1 garbage collector prints nothing after my algorithm starts. Presumably the G1 garbage collector is doing something (concurrent mark?), but it's not printing anything about it.</div>
<div><br></div><div>When run with VM args "-XX:+UseG1GC -verbose:gc" I get output like this (note the huge CPU load value which should not be this high for a single-threaded algorithm on an 8 core CPU):</div><div>
<br></div><blockquote style="margin:0px 0px 0px 40px;border:none;padding:0px"><div><div>[GC pause (young) 62M->62M(254M), 0.0394214 secs]</div></div><div><div>[GC pause (young) 73M->83M(508M), 0.0302781 secs]</div>
</div>
<div><div>[GC pause (young) 106M->111M(1016M), 0.0442273 secs]</div></div><div><div>[GC pause (young) 157M->161M(1625M), 0.0660902 secs]</div></div><div><div>[GC pause (young) 235M->240M(2112M), 0.0907231 secs]</div>
</div><div><div>[GC pause (young) 334M->337M(2502M), 0.1356917 secs]</div></div><div><div>[GC pause (young) 448M->450M(2814M), 0.1219090 secs]</div></div><div><div>[GC pause (young) 574M->577M(3064M), 0.1778062 secs]</div>
</div><div><div>[GC pause (young) 712M->715M(3264M), 0.1878443 secs]</div></div><div><div>CPU Load Is -1.0</div></div><div><div><br></div></div><div><div>Start</div></div><div><div>Stop</div></div><div><div>Sleep</div>
</div><div><div>CPU Load Is 0.9196154547182949</div></div><div><div><br></div></div><div><div>Start</div></div><div><div>Stop</div></div><div><div>Sleep</div></div><div><div>CPU Load Is 0.9150735995043818</div></div><div>
<br></div><div>...</div></blockquote><div><br></div><div><br></div><div>When run with VM args "-XX:+UseParallelGC -verbose:gc" I get output like this:<br></div><div><br></div><blockquote style="margin:0px 0px 0px 40px;border:none;padding:0px">
<div><div>[GC 65536K->64198K(249344K), 0.0628289 secs]</div></div><div><div>[GC 129734K->127974K(314880K), 0.1583369 secs]</div></div><div><div>[Full GC 127974K->127630K(451072K), 0.9675224 secs]</div></div><div>
<div>[GC 258702K->259102K(451072K), 0.3543645 secs]</div></div><div><div>[Full GC 259102K->258701K(732672K), 1.8085702 secs]</div></div><div><div>[GC 389773K->390181K(790528K), 0.3332060 secs]</div></div><div><div>
[GC 579109K->579717K(803328K), 0.5126388 secs]</div></div><div><div>[Full GC 579717K->578698K(1300480K), 4.0647303 secs]</div></div><div><div>[GC 780426K->780842K(1567232K), 0.4364933 secs]</div></div><div><div>
CPU Load Is -1.0</div>
</div><div><div><br></div></div><div><div>Start</div></div><div><div>Stop</div></div><div><div>Sleep</div></div><div><div>CPU Load Is 0.03137771539054431</div></div><div><div><br></div></div><div><div>Start</div></div><div>
<div>Stop</div></div><div><div>Sleep</div></div><div><div>CPU Load Is 0.032351299224373145</div></div><div><br></div><div>...</div></blockquote><div><br></div><div><br></div><div>When run with VM args "-verbose:gc" I get output like this:<br>
</div><div><br></div><blockquote style="margin:0px 0px 0px 40px;border:none;padding:0px"><div><div>[GC 69312K->67824K(251136K), 0.1533803 secs]</div></div><div><div>[GC 137136K->135015K(251136K), 0.0970460 secs]</div>
</div><div><div>[GC 137245K(251136K), 0.0095245 secs]</div></div><div><div>[GC 204327K->204326K(274368K), 0.1056259 secs]</div></div><div><div>[GC 273638K->273636K(343680K), 0.1081515 secs]</div></div><div><div>[GC 342948K->342946K(412992K), 0.1181966 secs]</div>
</div><div><div>[GC 412258K->412257K(482304K), 0.1126966 secs]</div></div><div><div>[GC 481569K->481568K(551808K), 0.1156015 secs]</div></div><div><div>[GC 550880K->550878K(620928K), 0.1184089 secs]</div></div><div>
<div>[GC 620190K->620189K(690048K), 0.1209312 secs]</div></div><div><div>[GC 689501K->689499K(759552K), 0.1199338 secs]</div></div><div><div>[GC 758811K->758809K(828864K), 0.1162532 secs]</div></div><div><div>CPU Load Is -1.0</div>
</div><div><div><br></div></div><div><div>Start</div></div><div><div>Stop</div></div><div><div>Sleep</div></div><div><div>CPU Load Is 0.10791719146608299</div></div><div><div><br></div></div><div><div>Start</div></div><div>
<div>[GC 821213K(828864K), 0.1966807 secs]</div></div><div><div>Stop</div></div><div><div>Sleep</div></div><div><div>CPU Load Is 0.1540065314146181</div></div><div><div><br></div></div><div><div>Start</div></div><div><div>
Stop</div></div><div><div>Sleep</div></div><div><div>[GC 821213K(1328240K), 0.1962688 secs]</div></div><div><div>CPU Load Is 0.08427292195744103</div></div><div><br></div><div>...</div></blockquote><div><br></div><div><br>
</div><div>Why is the G1 garbage collector consuming so much CPU time? Is it stuck in the mark phase as I am modifying the graph structure?</div><div><br></div><div>I'm not a subscriber to the list, so please CC me in any response.</div>
<div><br></div><div>Thanks,<br>Peter.</div><div><br></div><div>--</div><div><br></div><div><div>import java.lang.management.ManagementFactory;</div><div>import com.sun.management.OperatingSystemMXBean;</div><div>import java.util.Random;</div>
<div><br></div><div>@SuppressWarnings("restriction")</div><div>public class Node {</div><div><span style="white-space:pre-wrap"> </span>private static OperatingSystemMXBean os = (OperatingSystemMXBean) ManagementFactory.getOperatingSystemMXBean();</div>
<div><br></div><div><span style="white-space:pre-wrap"> </span>private Node next;</div><div><br></div><div><span style="white-space:pre-wrap"> </span>private Node[] others = new Node[10];</div><div><br></div><div>
<span style="white-space:pre-wrap"> </span>public static void main(String[] args) throws InterruptedException {</div><div><br></div><div><span style="white-space:pre-wrap"> </span>// Build a graph of Nodes</div><div>
<span style="white-space:pre-wrap"> </span>Node head = buildGraph();</div><div><br></div><div><span style="white-space:pre-wrap"> </span>while (true) {</div><div><span style="white-space:pre-wrap"> </span>// Print CPU load for this process</div>
<div><span style="white-space:pre-wrap"> </span>System.out.println("CPU Load Is " + os.getProcessCpuLoad());</div><div><span style="white-space:pre-wrap"> </span>System.out.println();</div><div><br></div>
<div><span style="white-space:pre-wrap"> </span>// Modify the graph</div><div><span style="white-space:pre-wrap"> </span>System.out.println("Start");</div><div><span style="white-space:pre-wrap"> </span>head = modifyGraph(head);</div>
<div><span style="white-space:pre-wrap"> </span>System.out.println("Stop");</div><div><br></div><div><span style="white-space:pre-wrap"> </span>// Sleep, as otherwise we tend to DoS the host computer...</div>
<div><span style="white-space:pre-wrap"> </span>System.out.println("Sleep");</div><div><span style="white-space:pre-wrap"> </span>Thread.sleep(1000);</div><div><span style="white-space:pre-wrap"> </span>}</div>
<div><span style="white-space:pre-wrap"> </span>}</div><div><br></div><div><span style="white-space:pre-wrap"> </span>private static Node buildGraph() {</div><div><br></div><div><span style="white-space:pre-wrap"> </span>// Create a collection of Node objects</div>
<div><span style="white-space:pre-wrap"> </span>Node[] array = new Node[10000000];</div><div><span style="white-space:pre-wrap"> </span>for (int i = 0; i < array.length; i++) {</div><div><span style="white-space:pre-wrap"> </span>array[i] = new Node();</div>
<div><span style="white-space:pre-wrap"> </span>}</div><div><br></div><div><span style="white-space:pre-wrap"> </span>// Each Node refers to 10 other random Nodes</div><div><span style="white-space:pre-wrap"> </span>Random random = new Random(12);</div>
<div><span style="white-space:pre-wrap"> </span>for (int i = 0; i < array.length; i++) {</div><div><span style="white-space:pre-wrap"> </span>for (int j = 0; j < array[i].others.length; j++) {</div><div><span style="white-space:pre-wrap"> </span>int k = random.nextInt(array.length);</div>
<div><span style="white-space:pre-wrap"> </span>array[i].others[j] = array[k];</div><div><span style="white-space:pre-wrap"> </span>}</div><div><span style="white-space:pre-wrap"> </span>}</div><div><br>
</div><div><span style="white-space:pre-wrap"> </span>// The first Node serves as the head of a queue</div><div><span style="white-space:pre-wrap"> </span>return array[0];</div><div><span style="white-space:pre-wrap"> </span>}</div>
<div><br></div><div><span style="white-space:pre-wrap"> </span>private static Node modifyGraph(Node head) {</div><div><br></div><div><span style="white-space:pre-wrap"> </span>// Perform a million iterations</div>
<div><span style="white-space:pre-wrap"> </span>for (int i = 0; i < 1000000; i++) {</div><div><br></div><div><span style="white-space:pre-wrap"> </span>// Pop a Node off the head of the queue</div><div><span style="white-space:pre-wrap"> </span>Node node = head;</div>
<div><span style="white-space:pre-wrap"> </span>head = node.next;</div><div><span style="white-space:pre-wrap"> </span>node.next = null;</div><div><br></div><div><span style="white-space:pre-wrap"> </span>// Add the other Nodes to the head of the queue</div>
<div><span style="white-space:pre-wrap"> </span>for (Node other : node.others) {</div><div><span style="white-space:pre-wrap"> </span>other.next = head;</div><div><span style="white-space:pre-wrap"> </span>head = other;</div>
<div><span style="white-space:pre-wrap"> </span>}</div><div><span style="white-space:pre-wrap"> </span>}</div><div><span style="white-space:pre-wrap"> </span>return head;</div><div><span style="white-space:pre-wrap"> </span>}</div>
<div><br></div><div>}</div></div><span><font color="#888888"><div><br></div><div>-- <br><b>Actenum Corporation</b><br>Peter Harvey | Cell: <a href="tel:780.729.8192" value="+17807298192" target="_blank">780.729.8192</a> | <a href="mailto:harvey@actenum.com" target="_blank">harvey@actenum.com</a> | <a href="http://www.actenum.com" target="_blank">www.actenum.com</a>
</div></font></span></div>
</blockquote></div><br><br clear="all"><div><br></div>-- <br><b>Actenum Corporation</b><br>Peter Harvey | Cell: <a href="tel:780.729.8192" value="+17807298192" target="_blank">780.729.8192</a> | <a href="mailto:harvey@actenum.com" target="_blank">harvey@actenum.com</a> | <a href="http://www.actenum.com" target="_blank">www.actenum.com</a>
</div>
</div></div></blockquote></div><br></div>
</div></div></blockquote></div><br></div>
</div></div></blockquote></div><br><br clear="all"><div><br></div>-- <br><b>Actenum Corporation</b><br>Peter Harvey | Cell: 780.729.8192 | <a href="mailto:harvey@actenum.com" target="_blank">harvey@actenum.com</a> | <a href="http://www.actenum.com" target="_blank">www.actenum.com</a>
</div>