G1 GC consuming all CPU time

Tue Jun 3 21:13:45 UTC 2014

Hi Peter,

What was your actual question? Try -XX:ParallelGCThreads=<value> if you
want less CPU usage from GC.

Thanks.
Tao

On Tue, Jun 3, 2014 at 11:49 AM, Peter Harvey <harvey at actenum.com> wrote:

> 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/544d5f7d/attachment.htm>