G1 GC consuming all CPU time

[Peter Harvey]

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.

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.

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):

[GC pause (young) 62M->62M(254M), 0.0394214 secs]
[GC pause (young) 73M->83M(508M), 0.0302781 secs]
[GC pause (young) 106M->111M(1016M), 0.0442273 secs]
[GC pause (young) 157M->161M(1625M), 0.0660902 secs]
[GC pause (young) 235M->240M(2112M), 0.0907231 secs]
[GC pause (young) 334M->337M(2502M), 0.1356917 secs]
[GC pause (young) 448M->450M(2814M), 0.1219090 secs]
[GC pause (young) 574M->577M(3064M), 0.1778062 secs]
[GC pause (young) 712M->715M(3264M), 0.1878443 secs]
CPU Load Is -1.0

Start
Stop
Sleep
CPU Load Is 0.9196154547182949

Start
Stop
Sleep
CPU Load Is 0.9150735995043818

...



When run with VM args "-XX:+UseParallelGC -verbose:gc" I get output like
this:

[GC 65536K->64198K(249344K), 0.0628289 secs]
[GC 129734K->127974K(314880K), 0.1583369 secs]
[Full GC 127974K->127630K(451072K), 0.9675224 secs]
[GC 258702K->259102K(451072K), 0.3543645 secs]
[Full GC 259102K->258701K(732672K), 1.8085702 secs]
[GC 389773K->390181K(790528K), 0.3332060 secs]
[GC 579109K->579717K(803328K), 0.5126388 secs]
[Full GC 579717K->578698K(1300480K), 4.0647303 secs]
[GC 780426K->780842K(1567232K), 0.4364933 secs]
CPU Load Is -1.0

Start
Stop
Sleep
CPU Load Is 0.03137771539054431

Start
Stop
Sleep
CPU Load Is 0.032351299224373145

...



When run with VM args "-verbose:gc" I get output like this:

[GC 69312K->67824K(251136K), 0.1533803 secs]
[GC 137136K->135015K(251136K), 0.0970460 secs]
[GC 137245K(251136K), 0.0095245 secs]
[GC 204327K->204326K(274368K), 0.1056259 secs]
[GC 273638K->273636K(343680K), 0.1081515 secs]
[GC 342948K->342946K(412992K), 0.1181966 secs]
[GC 412258K->412257K(482304K), 0.1126966 secs]
[GC 481569K->481568K(551808K), 0.1156015 secs]
[GC 550880K->550878K(620928K), 0.1184089 secs]
[GC 620190K->620189K(690048K), 0.1209312 secs]
[GC 689501K->689499K(759552K), 0.1199338 secs]
[GC 758811K->758809K(828864K), 0.1162532 secs]
CPU Load Is -1.0

Start
Stop
Sleep
CPU Load Is 0.10791719146608299

Start
[GC 821213K(828864K), 0.1966807 secs]
Stop
Sleep
CPU Load Is 0.1540065314146181

Start
Stop
Sleep
[GC 821213K(1328240K), 0.1962688 secs]
CPU Load Is 0.08427292195744103

...



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?

I'm not a subscriber to the list, so please CC me in any response.

Thanks,
Peter.

--

import java.lang.management.ManagementFactory;
import com.sun.management.OperatingSystemMXBean;
import java.util.Random;

@SuppressWarnings("restriction")
public class Node {
private static OperatingSystemMXBean os = (OperatingSystemMXBean)
ManagementFactory.getOperatingSystemMXBean();

private Node next;

private Node[] others = new Node[10];

public static void main(String[] args) throws InterruptedException {

// Build a graph of Nodes
Node head = buildGraph();

while (true) {
// Print CPU load for this process
System.out.println("CPU Load Is " + os.getProcessCpuLoad());
System.out.println();

// Modify the graph
System.out.println("Start");
head = modifyGraph(head);
System.out.println("Stop");

// Sleep, as otherwise we tend to DoS the host computer...
System.out.println("Sleep");
Thread.sleep(1000);
}
}

private static Node buildGraph() {

// Create a collection of Node objects
Node[] array = new Node[10000000];
for (int i = 0; i < array.length; i++) {
array[i] = new Node();
}

// Each Node refers to 10 other random Nodes
Random random = new Random(12);
for (int i = 0; i < array.length; i++) {
for (int j = 0; j < array[i].others.length; j++) {
int k = random.nextInt(array.length);
array[i].others[j] = array[k];
}
}

// The first Node serves as the head of a queue
return array[0];
}

private static Node modifyGraph(Node head) {

// Perform a million iterations
for (int i = 0; i < 1000000; i++) {

// Pop a Node off the head of the queue
Node node = head;
head = node.next;
node.next = null;

// Add the other Nodes to the head of the queue
for (Node other : node.others) {
other.next = head;
head = other;
}
}
return head;
}

}

-- 
*Actenum Corporation*
Peter Harvey  |  Cell: 780.729.8192  |  harvey at actenum.com  |
www.actenum.com
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20140603/3149900e/attachment.htm>