G1 GC consuming all CPU time

Tue Jun 3 21:16:52 UTC 2014

And, use –XX:+PrintGCDetails –XX:+PrintGCTimeStamps to get more log.
Thanks. -Tao

On Tue, Jun 3, 2014 at 2:13 PM, Tao Mao <yiyeguhu at gmail.com> wrote:

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