G1 GC consuming all CPU time

[Peter Harvey]

Small correction. The last example of output was with
"-XX:+UseConcMarkSweepGC -verbose:gc".


On Tue, Jun 3, 2014 at 12:41 PM, Peter Harvey <harvey at actenum.com> wrote:

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



-- 
*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/33e31f29/attachment.htm>