<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><div>Tao</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 class="HOEnZb"><div class="h5"><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>