<html><head><meta http-equiv="Content-Type" content="text/html; charset=UTF-8"></head><body ><div><span class="Apple-style-span" style="color: rgb(87, 87, 87); font-size: 9px; ">At least CPU load is down, suggesting its no longer a concurrency issue. One thing that comes to mind is that G1 emits costly write and read barriers that heavily penalize interpreted code, while JMH generally avoid that benchmarking trap. Try extracting the loop body in your test into a method to help the JIT along and see if that evens out the playing field?</span></div><div><span class="Apple-style-span" style="color: rgb(87, 87, 87); font-size: 9px; "><br></span></div><div><span class="Apple-style-span" style="color: rgb(87, 87, 87); font-size: 9px; ">/Claes.</span></div><div></div><br><br>-------- Originalmeddelande --------<br>Från: Peter Harvey <harvey@actenum.com> <br>Datum:04-06-2014 01:12 (GMT+01:00) <br>Till: Claes Redestad <claes.redestad@oracle.com> <br>Kopia: hotspot-gc-dev <hotspot-gc-dev@openjdk.java.net> <br>Rubrik: Re: G1 GC consuming all CPU time <br><br><div dir="ltr">Here's my list of benchmarks from the previous email:<div><ul style=""><li style="font-family:arial,sans-serif;font-size:13px;margin-left:15px">-XX:+UseG1GC -XX:ParallelGCThreads=1 took 82.393 seconds and CPU load was 0.1247</li>
<li style="font-family:arial,sans-serif;font-size:13px;margin-left:15px">-XX:+UseG1GC -XX:ParallelGCThreads=4 took 19.829 seconds and CPU load was 0.5960</li><li style="font-family:arial,sans-serif;font-size:13px;margin-left:15px">
-XX:+UseG1GC -XX:ParallelGCThreads=8 took 14.815 seconds and CPU load was 0.9184<br></li><li style="font-family:arial,sans-serif;font-size:13px;margin-left:15px">-XX:+UseConcMarkSweepGC took 0.322 seconds and CPU load was 0.1119 regardless of the setting of -XX:ParallelGCThreads</li>
</ul><div><font face="arial, sans-serif">And here's using those new parameters with my original code:</font></div><ul style=""><li style="margin-left:15px"><font face="arial, sans-serif">-XX:+UseG1GC -XX:-G1UseAdaptiveConcRefinement -XX:G1ConcRefinementThreads=1 took 53.077 seconds and CPU load was 0.1237</font><br>
</li></ul><div><font face="arial, sans-serif">I may be completely misunderstanding the implications of your JMH tests, but those parameters don't seem to improve overall application performance when using my original code.</font></div>
<div><font face="arial, sans-serif"><br></font></div><div><font face="arial, sans-serif">It looks to me like the use of the G1 garbage collector is somehow also slowing down the application itself (but not necessarily your JMH test?). Not only are the GC threads tripping over each other, they seem to be tripping up the main application thread too.</font></div>
</div><div><font face="arial, sans-serif"><br></font></div><div><font face="arial, sans-serif">Regards,</font></div><div><font face="arial, sans-serif">Peter.</font></div><div><font face="arial, sans-serif"><br></font></div>
<div><font face="arial, sans-serif"><br></font></div></div><div class="gmail_extra"><br><br><div class="gmail_quote">On Tue, Jun 3, 2014 at 4:57 PM, Claes Redestad <span dir="ltr"><<a href="mailto:claes.redestad@oracle.com" target="_blank">claes.redestad@oracle.com</a>></span> wrote:<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">Hi,<br>
<br>
guessing it's due to the concurrent GC threads tripping over themselves: the microbenchmark is creating one, big linked structure that will occupy most of the old gen, and then you're doing intense pointer updates which will trigger scans and updates of remembered sets etc. I actually don't know half the details and am mostly just guessing. :-)<br>
<br>
Converted your micro to a JMH micro to ease with experimenting[1] (hope you don't mind) then verified the regression reproduces:<br>
<br>
Parallel:<br>
java -jar target/microbenchmarks.jar -wi 3 -i 10 -f 1 .*G1GraphBench.*<br>
~1625 ops/ms<br>
<br>
G1:<br>
java -XX:+UseG1GC -jar target/microbenchmarks.jar -wi 3 -i 10 -f 1 .*G1GraphBench.*<br>
~12 ops/ms<br>
<br>
Testing my hunch, let's try forcing the concurrent refinement to use only one thread:<br>
<br>
java -XX:+UseG1GC -XX:-<u></u>G1UseAdaptiveConcRefinement -XX:G1ConcRefinementThreads=1 -jar target/microbenchmarks.jar -wi 3 -i 10 -f 1 .*G1GraphBench.*<br>
~1550 ops/ms<br>
<br>
I guess we have a winner! I won't hazard to try and answer your questions about how this should be resolved - perhaps the adaptive policy can detect this corner case and scale down the number of refinement threads when they start interfering with each other, or something.<br>
<br>
/Claes<br>
<br>
[1]<br>
<br>
package org.sample;<br>
<br>
import org.openjdk.jmh.annotations.<u></u>GenerateMicroBenchmark;<br>
import org.openjdk.jmh.annotations.<u></u>Scope;<br>
import org.openjdk.jmh.annotations.<u></u>State;<br>
<br>
import java.util.Random;<br>
<br>
@State(Scope.Thread)<br>
public class G1GraphBench {<br>
<br>
private static class Node {<div class=""><br>
private Node next;<br>
private Node[] others = new Node[10];<br>
}<br>
<br></div>
Node head = buildGraph();<div class=""><br>
<br>
private static Node buildGraph() {<br>
<br>
// Create a collection of Node objects<br>
Node[] array = new Node[10000000];<br>
for (int i = 0; i < array.length; i++) {<br>
array[i] = new Node();<br>
}<br>
<br>
// Each Node refers to 10 other random Nodes<br>
Random random = new Random(12);<br>
for (int i = 0; i < array.length; i++) {<br>
for (int j = 0; j < array[i].others.length; j++) {<br>
int k = random.nextInt(array.length);<br>
array[i].others[j] = array[k];<br>
}<br>
}<br>
<br>
// The first Node serves as the head of a queue<br>
return array[0];<br>
}<br>
<br></div>
@GenerateMicroBenchmark<br>
public Node nodeBench() {<div class=""><br>
Node node = head;<br>
head = node.next;<br>
node.next = null;<br>
<br>
// Add the other Nodes to the head of the queue<br>
for (Node other : node.others) {<br>
other.next = head;<br>
head = other;<br>
}<br>
return head;<br>
}<br>
<br>
}<br>
<br></div><div><div class="h5">
On 2014-06-03 23:43, Peter Harvey wrote:<br>
</div></div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div><div class="h5">
Thanks for the response. Here are the additional logs.<br>
<br>
0.094: [GC pause (young), 0.0347877 secs]<br>
[Parallel Time: 34.1 ms, GC Workers: 8]<br>
[GC Worker Start (ms): Min: 94.2, Avg: 104.4, Max: 126.4,<br>
Diff: 32.2]<br>
[Ext Root Scanning (ms): Min: 0.0, Avg: 3.3, Max: 25.0,<br>
Diff: 25.0, Sum: 26.6]<br>
[Update RS (ms): Min: 0.0, Avg: 2.1, Max: 5.3, Diff: 5.3,<br>
Sum: 16.7]<br>
[Processed Buffers: Min: 0, Avg: 2.3, Max: 9, Diff: 9,<br>
Sum: 18]<br>
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum:<br>
0.0]<br>
[Object Copy (ms): Min: 1.8, Avg: 18.3, Max: 29.9, Diff:<br>
28.2, Sum: 146.4]<br>
[Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1,<br>
Sum: 0.6]<br>
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff:<br>
0.0, Sum: 0.1]<br>
[GC Worker Total (ms): Min: 1.9, Avg: 23.8, Max: 34.1, Diff:<br>
32.2, Sum: 190.4]<br>
[GC Worker End (ms): Min: 128.2, Avg: 128.3, Max: 128.3,<br>
Diff: 0.0]<br>
[Code Root Fixup: 0.0 ms]<br>
[Clear CT: 0.0 ms]<br>
[Other: 0.6 ms]<br>
[Choose CSet: 0.0 ms]<br>
[Ref Proc: 0.3 ms]<br>
[Ref Enq: 0.0 ms]<br>
[Free CSet: 0.0 ms]<br>
[Eden: 24.0M(24.0M)->0.0B(11.0M) Survivors: 0.0B->3072.0K Heap:<br>
62.1M(254.0M)->62.2M(254.0M)]<br>
[Times: user=0.09 sys=0.03, real=0.04 secs]<br>
0.131: [GC pause (young), 0.0295093 secs]<br>
[Parallel Time: 28.1 ms, GC Workers: 8]<br>
[GC Worker Start (ms): Min: 130.9, Avg: 135.5, Max: 158.7,<br>
Diff: 27.8]<br>
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff:<br>
0.4, Sum: 1.2]<br>
[Update RS (ms): Min: 0.0, Avg: 11.4, Max: 27.5, Diff: 27.5,<br>
Sum: 90.8]<br>
[Processed Buffers: Min: 0, Avg: 23.8, Max: 42, Diff: 42,<br>
Sum: 190]<br>
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum:<br>
0.0]<br>
[Object Copy (ms): Min: 0.0, Avg: 11.7, Max: 17.1, Diff:<br>
17.1, Sum: 93.8]<br>
[Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3,<br>
Sum: 1.7]<br>
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff:<br>
0.0, Sum: 0.1]<br>
[GC Worker Total (ms): Min: 0.2, Avg: 23.5, Max: 28.1, Diff:<br>
27.8, Sum: 187.7]<br>
[GC Worker End (ms): Min: 159.0, Avg: 159.0, Max: 159.0,<br>
Diff: 0.0]<br>
[Code Root Fixup: 0.0 ms]<br>
[Clear CT: 0.1 ms]<br>
[Other: 1.3 ms]<br>
[Choose CSet: 0.0 ms]<br>
[Ref Proc: 0.1 ms]<br>
[Ref Enq: 0.0 ms]<br>
[Free CSet: 0.0 ms]<br>
[Eden: 11.0M(11.0M)->0.0B(23.0M) Survivors: 3072.0K->2048.0K<br>
Heap: 73.2M(254.0M)->82.7M(508.0M)]<br>
[Times: user=0.19 sys=0.00, real=0.03 secs]<br>
0.166: [GC pause (young), 0.0385523 secs]<br>
[Parallel Time: 35.9 ms, GC Workers: 8]<br>
[GC Worker Start (ms): Min: 166.4, Avg: 169.8, Max: 192.4,<br>
Diff: 25.9]<br>
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff:<br>
0.4, Sum: 1.9]<br>
[Update RS (ms): Min: 0.0, Avg: 10.9, Max: 31.9, Diff: 31.9,<br>
Sum: 87.2]<br>
[Processed Buffers: Min: 0, Avg: 14.6, Max: 26, Diff: 26,<br>
Sum: 117]<br>
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum:<br>
0.1]<br>
[Object Copy (ms): Min: 3.5, Avg: 21.4, Max: 27.0, Diff:<br>
23.4, Sum: 171.1]<br>
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1,<br>
Sum: 0.4]<br>
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff:<br>
0.0, Sum: 0.1]<br>
[GC Worker Total (ms): Min: 10.0, Avg: 32.6, Max: 35.9,<br>
Diff: 25.9, Sum: 260.7]<br>
[GC Worker End (ms): Min: 202.3, Avg: 202.4, Max: 202.4,<br>
Diff: 0.0]<br>
[Code Root Fixup: 0.0 ms]<br>
[Clear CT: 0.0 ms]<br>
[Other: 2.6 ms]<br>
[Choose CSet: 0.0 ms]<br>
[Ref Proc: 0.1 ms]<br>
[Ref Enq: 0.0 ms]<br>
[Free CSet: 0.0 ms]<br>
[Eden: 23.0M(23.0M)->0.0B(46.0M) Survivors: 2048.0K->4096.0K<br>
Heap: 105.7M(508.0M)->110.1M(1016.<u></u>0M)]<br>
[Times: user=0.19 sys=0.00, real=0.04 secs]<br>
0.222: [GC pause (young), 0.0558720 secs]<br>
[Parallel Time: 53.0 ms, GC Workers: 8]<br>
[GC Worker Start (ms): Min: 222.0, Avg: 222.2, Max: 222.5,<br>
Diff: 0.5]<br>
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff:<br>
0.4, Sum: 1.5]<br>
[Update RS (ms): Min: 7.7, Avg: 8.7, Max: 10.9, Diff: 3.2,<br>
Sum: 69.4]<br>
[Processed Buffers: Min: 7, Avg: 8.5, Max: 12, Diff: 5,<br>
Sum: 68]<br>
[Scan RS (ms): Min: 0.0, Avg: 0.3, Max: 0.6, Diff: 0.6, Sum:<br>
2.3]<br>
[Object Copy (ms): Min: 41.7, Avg: 43.6, Max: 44.3, Diff:<br>
2.7, Sum: 348.5]<br>
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0,<br>
Sum: 0.0]<br>
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff:<br>
0.0, Sum: 0.2]<br>
[GC Worker Total (ms): Min: 52.4, Avg: 52.7, Max: 52.9,<br>
Diff: 0.5, Sum: 421.8]<br>
[GC Worker End (ms): Min: 274.9, Avg: 274.9, Max: 274.9,<br>
Diff: 0.0]<br>
[Code Root Fixup: 0.0 ms]<br>
[Clear CT: 0.0 ms]<br>
[Other: 2.8 ms]<br>
[Choose CSet: 0.0 ms]<br>
[Ref Proc: 0.1 ms]<br>
[Ref Enq: 0.0 ms]<br>
[Free CSet: 0.0 ms]<br>
[Eden: 46.0M(46.0M)->0.0B(74.0M) Survivors: 4096.0K->7168.0K<br>
Heap: 156.1M(1016.0M)->158.6M(1625.<u></u>0M)]<br>
[Times: user=0.48 sys=0.01, real=0.06 secs]<br>
0.328: [GC pause (young), 0.0853794 secs]<br>
[Parallel Time: 82.8 ms, GC Workers: 8]<br>
[GC Worker Start (ms): Min: 327.9, Avg: 330.8, Max: 351.1,<br>
Diff: 23.2]<br>
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff:<br>
0.3, Sum: 2.0]<br>
[Update RS (ms): Min: 0.0, Avg: 5.5, Max: 8.3, Diff: 8.3,<br>
Sum: 43.9]<br>
[Processed Buffers: Min: 0, Avg: 2.3, Max: 3, Diff: 3,<br>
Sum: 18]<br>
[Scan RS (ms): Min: 0.0, Avg: 2.2, Max: 3.3, Diff: 3.3, Sum:<br>
17.4]<br>
[Object Copy (ms): Min: 59.5, Avg: 71.8, Max: 73.7, Diff:<br>
14.2, Sum: 574.7]<br>
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0,<br>
Sum: 0.2]<br>
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff:<br>
0.0, Sum: 0.2]<br>
[GC Worker Total (ms): Min: 59.5, Avg: 79.8, Max: 82.7,<br>
Diff: 23.2, Sum: 638.4]<br>
[GC Worker End (ms): Min: 410.6, Avg: 410.7, Max: 410.7,<br>
Diff: 0.0]<br>
[Code Root Fixup: 0.0 ms]<br>
[Clear CT: 0.1 ms]<br>
[Other: 2.6 ms]<br>
[Choose CSet: 0.0 ms]<br>
[Ref Proc: 0.1 ms]<br>
[Ref Enq: 0.0 ms]<br>
[Free CSet: 0.1 ms]<br>
[Eden: 74.0M(74.0M)->0.0B(94.0M) Survivors: 7168.0K->11.0M<br>
Heap: 232.6M(1625.0M)->237.6M(2112.<u></u>0M)]<br>
[Times: user=0.59 sys=0.00, real=0.09 secs]<br>
0.447: [GC pause (young), 0.1239103 secs]<br>
[Parallel Time: 121.5 ms, GC Workers: 8]<br>
[GC Worker Start (ms): Min: 447.5, Avg: 447.7, Max: 448.5,<br>
Diff: 0.9]<br>
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff:<br>
0.3, Sum: 1.9]<br>
[Update RS (ms): Min: 26.5, Avg: 28.2, Max: 28.7, Diff: 2.2,<br>
Sum: 225.7]<br>
[Processed Buffers: Min: 38, Avg: 39.8, Max: 44, Diff: 6,<br>
Sum: 318]<br>
[Scan RS (ms): Min: 0.3, Avg: 0.7, Max: 1.9, Diff: 1.6, Sum:<br>
5.3]<br>
[Object Copy (ms): Min: 92.1, Avg: 92.2, Max: 92.3, Diff:<br>
0.2, Sum: 737.5]<br>
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1,<br>
Sum: 0.3]<br>
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff:<br>
0.0, Sum: 0.2]<br>
[GC Worker Total (ms): Min: 120.6, Avg: 121.4, Max: 121.5,<br>
Diff: 0.9, Sum: 970.8]<br>
[GC Worker End (ms): Min: 569.0, Avg: 569.0, Max: 569.0,<br>
Diff: 0.0]<br>
[Code Root Fixup: 0.0 ms]<br>
[Clear CT: 0.1 ms]<br>
[Other: 2.3 ms]<br>
[Choose CSet: 0.0 ms]<br>
[Ref Proc: 0.1 ms]<br>
[Ref Enq: 0.0 ms]<br>
[Free CSet: 0.1 ms]<br>
[Eden: 94.0M(94.0M)->0.0B(111.0M) Survivors: 11.0M->14.0M Heap:<br>
331.6M(2112.0M)->334.6M(2502.<u></u>0M)]<br>
[Times: user=0.80 sys=0.05, real=0.12 secs]<br>
0.599: [GC pause (young), 0.1479438 secs]<br>
[Parallel Time: 145.7 ms, GC Workers: 8]<br>
[GC Worker Start (ms): Min: 599.4, Avg: 599.5, Max: 599.8,<br>
Diff: 0.4]<br>
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff:<br>
0.3, Sum: 1.9]<br>
[Update RS (ms): Min: 41.8, Avg: 43.0, Max: 44.0, Diff: 2.1,<br>
Sum: 343.6]<br>
[Processed Buffers: Min: 67, Avg: 70.9, Max: 73, Diff: 6,<br>
Sum: 567]<br>
[Scan RS (ms): Min: 0.0, Avg: 0.8, Max: 1.9, Diff: 1.9, Sum:<br>
6.2]<br>
[Object Copy (ms): Min: 101.3, Avg: 101.6, Max: 101.7, Diff:<br>
0.3, Sum: 812.6]<br>
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0,<br>
Sum: 0.1]<br>
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff:<br>
0.0, Sum: 0.2]<br>
[GC Worker Total (ms): Min: 145.2, Avg: 145.6, Max: 145.6,<br>
Diff: 0.4, Sum: 1164.6]<br>
[GC Worker End (ms): Min: 745.1, Avg: 745.1, Max: 745.1,<br>
Diff: 0.0]<br>
[Code Root Fixup: 0.0 ms]<br>
[Clear CT: 0.1 ms]<br>
[Other: 2.2 ms]<br>
[Choose CSet: 0.0 ms]<br>
[Ref Proc: 0.1 ms]<br>
[Ref Enq: 0.0 ms]<br>
[Free CSet: 0.1 ms]<br>
[Eden: 111.0M(111.0M)->0.0B(124.0M) Survivors: 14.0M->16.0M<br>
Heap: 445.6M(2502.0M)->448.6M(2814.<u></u>0M)]<br>
[Times: user=1.20 sys=0.05, real=0.15 secs]<br>
0.787: [GC pause (young), 0.1625321 secs]<br>
[Parallel Time: 160.0 ms, GC Workers: 8]<br>
[GC Worker Start (ms): Min: 786.6, Avg: 786.7, Max: 786.9,<br>
Diff: 0.4]<br>
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff:<br>
0.3, Sum: 1.8]<br>
[Update RS (ms): Min: 46.4, Avg: 47.0, Max: 49.0, Diff: 2.5,<br>
Sum: 376.0]<br>
[Processed Buffers: Min: 75, Avg: 78.0, Max: 79, Diff: 4,<br>
Sum: 624]<br>
[Scan RS (ms): Min: 0.0, Avg: 0.9, Max: 1.5, Diff: 1.5, Sum:<br>
7.4]<br>
[Object Copy (ms): Min: 110.6, Avg: 111.7, Max: 112.0, Diff:<br>
1.4, Sum: 893.5]<br>
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0,<br>
Sum: 0.1]<br>
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff:<br>
0.1, Sum: 0.3]<br>
[GC Worker Total (ms): Min: 159.6, Avg: 159.9, Max: 160.0,<br>
Diff: 0.4, Sum: 1279.0]<br>
[GC Worker End (ms): Min: 946.5, Avg: 946.5, Max: 946.6,<br>
Diff: 0.1]<br>
[Code Root Fixup: 0.0 ms]<br>
[Clear CT: 0.1 ms]<br>
[Other: 2.4 ms]<br>
[Choose CSet: 0.0 ms]<br>
[Ref Proc: 0.1 ms]<br>
[Ref Enq: 0.0 ms]<br>
[Free CSet: 0.2 ms]<br>
[Eden: 124.0M(124.0M)->0.0B(135.0M) Survivors: 16.0M->18.0M<br>
Heap: 572.6M(2814.0M)->576.6M(3064.<u></u>0M)]<br>
[Times: user=1.37 sys=0.00, real=0.16 secs]<br>
0.981: [GC pause (young), 0.2063055 secs]<br>
[Parallel Time: 204.1 ms, GC Workers: 8]<br>
[GC Worker Start (ms): Min: 980.8, Avg: 980.9, Max: 981.0,<br>
Diff: 0.2]<br>
[Ext Root Scanning (ms): Min: 0.1, Avg: 0.3, Max: 0.3, Diff:<br>
0.2, Sum: 2.1]<br>
[Update RS (ms): Min: 55.9, Avg: 57.8, Max: 58.8, Diff: 2.9,<br>
Sum: 462.8]<br>
[Processed Buffers: Min: 100, Avg: 101.5, Max: 103, Diff:<br>
3, Sum: 812]<br>
[Scan RS (ms): Min: 0.0, Avg: 1.0, Max: 3.1, Diff: 3.1, Sum:<br>
8.3]<br>
[Object Copy (ms): Min: 144.7, Avg: 144.8, Max: 144.9, Diff:<br>
0.1, Sum: 1158.3]<br>
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0,<br>
Sum: 0.3]<br>
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff:<br>
0.0, Sum: 0.2]<br>
[GC Worker Total (ms): Min: 203.8, Avg: 204.0, Max: 204.0,<br>
Diff: 0.2, Sum: 1631.9]<br>
[GC Worker End (ms): Min: 1184.9, Avg: 1184.9, Max: 1184.9,<br>
Diff: 0.0]<br>
[Code Root Fixup: 0.0 ms]<br>
[Clear CT: 0.1 ms]<br>
[Other: 2.1 ms]<br>
[Choose CSet: 0.0 ms]<br>
[Ref Proc: 0.1 ms]<br>
[Ref Enq: 0.0 ms]<br>
[Free CSet: 0.1 ms]<br>
[Eden: 135.0M(135.0M)->0.0B(143.0M) Survivors: 18.0M->20.0M<br>
Heap: 711.6M(3064.0M)->714.6M(3264.<u></u>0M)]<br>
[Times: user=1.40 sys=0.11, real=0.21 secs]<br>
CPU Load Is -1.0<br>
<br>
Start<br>
Stop<br>
Sleep<br>
CPU Load Is 0.9166222455142531<br>
<br>
Start<br>
Stop<br>
Sleep<br>
CPU Load Is 0.907013989900451<br>
<br>
Start<br>
Stop<br>
Sleep<br>
CPU Load Is 0.9085635227776081<br>
<br>
Start<br>
Stop<br>
Sleep<br>
CPU Load Is 0.909945506396622<br>
<br>
<br>
<br></div></div>
Note that all the logged GC occurs during the construction of my graph of Nodes, which is /before/ my algorithm (modifyGraph) starts, There is no log of GC activity once the algorithm starts, but there is significant (100%) CPU usage.<br>
<br>
My questions are:<br>
<br>
* Why is the G1 garbage collector consuming so much CPU time? What<br>
is it doing?<br>
* Why is the G1 garbage collector not logging anything? The only<div class=""><br>
reason I even know it's the garbage collector consuming my CPU<br>
time is that (a) I only see this behaviour when the G1 collector<br>
is enabled and (b) the load on the CPU correlates with the value<br>
of -XX:ParallelGCThreads.<br></div>
* Are there particular object-graph structures that the G1 garbage<div class=""><br>
collector will struggle with? Should complex graphs be considered<br>
bad coding practice?<br></div>
* How can I write my code to avoid this behaviour in the G1 garbage<div class=""><br>
collector? For example, if all my Nodes are in an array, will this<br>
fix it?<br></div>
* Should this be considered a bug in the G1 garbage collector? This<div class=""><br>
is far beyond 'a small increase in CPU usage'.<br>
<br>
Just to demonstrate the issue further, I timed my calls to modifyGraph() and trialled different GC parameters:<br>
<br></div>
* -XX:+UseG1GC -XX:ParallelGCThreads=1 took 82.393 seconds and CPU<br>
load was 0.1247<br>
* -XX:+UseG1GC -XX:ParallelGCThreads=4 took 19.829 seconds and CPU<br>
load was 0.5960<br>
* -XX:+UseG1GC -XX:ParallelGCThreads=8 took 14.815 seconds and CPU<br>
load was 0.9184<br>
* -XX:+UseConcMarkSweepGC took 0.322 seconds and CPU load was 0.1119<div class=""><br>
regardless of the setting of -XX:ParallelGCThreads<br>
<br>
So using the CMS GC made my application 44x faster (14.815 seconds versus 0.322 seconds) and placed 1/8th of the load (0.9184 versus 0.1119) on the CPU.<br>
<br>
If my code represents some kind of hypothetical worst case for the G1 garbage collector, I think it should be documented and/or fixed somehow.<br>
<br>
Regards,<br>
Peter.<br>
<br>
<br>
<br></div><div class="">
On Tue, Jun 3, 2014 at 3:16 PM, Tao Mao <<a href="mailto:yiyeguhu@gmail.com" target="_blank">yiyeguhu@gmail.com</a> <mailto:<a href="mailto:yiyeguhu@gmail.com" target="_blank">yiyeguhu@gmail.com</a>>> wrote:<br>
<br>
And, use –XX:+PrintGCDetails –XX:+PrintGCTimeStamps to get more<br>
log. Thanks. -Tao<br>
<br>
<br>
On Tue, Jun 3, 2014 at 2:13 PM, Tao Mao <<a href="mailto:yiyeguhu@gmail.com" target="_blank">yiyeguhu@gmail.com</a><br></div><div class="">
<mailto:<a href="mailto:yiyeguhu@gmail.com" target="_blank">yiyeguhu@gmail.com</a>>> wrote:<br>
<br>
Hi Peter,<br>
<br>
What was your actual question?<br>
Try -XX:ParallelGCThreads=<value> if you want less CPU usage<br>
from GC.<br>
<br>
Thanks.<br>
Tao<br>
<br>
<br>
On Tue, Jun 3, 2014 at 11:49 AM, Peter Harvey<br></div><div class="">
<<a href="mailto:harvey@actenum.com" target="_blank">harvey@actenum.com</a> <mailto:<a href="mailto:harvey@actenum.com" target="_blank">harvey@actenum.com</a>>> wrote:<br>
<br>
Small correction. The last example of output was with<br>
"-XX:+UseConcMarkSweepGC -verbose:gc".<br>
<br>
<br>
On Tue, Jun 3, 2014 at 12:41 PM, Peter Harvey<br></div><div><div class="h5">
<<a href="mailto:harvey@actenum.com" target="_blank">harvey@actenum.com</a> <mailto:<a href="mailto:harvey@actenum.com" target="_blank">harvey@actenum.com</a>>> wrote:<br>
<br>
I have an algorithm (at bottom of email) which builds<br>
a graph of 'Node' objects with random connections<br>
between them. It then repeatedly processes a queue of<br>
those Nodes, adding new Nodes to the queue as it goes.<br>
This is a single-threaded algorithm that will never<br>
terminate. Our actual production code is much more<br>
complex, but I've trimmed it down as much as possible.<br>
<br>
On Windows 7 with JRE 7u60, enabling the G1 garbage<br>
collector will cause the JRE to consume all 8 cores of<br>
my CPU. No other garbage collector does this. You can<br>
see the differences in CPU load in the example output<br>
below. It's also worth nothing that "-verbose:gc" with<br>
the G1 garbage collector prints nothing after my<br>
algorithm starts. Presumably the G1 garbage collector<br>
is doing something (concurrent mark?), but it's not<br>
printing anything about it.<br>
<br>
When run with VM args "-XX:+UseG1GC -verbose:gc" I get<br>
output like this (note the huge CPU load value which<br>
should not be this high for a single-threaded<br>
algorithm on an 8 core CPU):<br>
<br>
[GC pause (young) 62M->62M(254M), 0.0394214 secs]<br>
[GC pause (young) 73M->83M(508M), 0.0302781 secs]<br>
[GC pause (young) 106M->111M(1016M), 0.0442273 secs]<br>
[GC pause (young) 157M->161M(1625M), 0.0660902 secs]<br>
[GC pause (young) 235M->240M(2112M), 0.0907231 secs]<br>
[GC pause (young) 334M->337M(2502M), 0.1356917 secs]<br>
[GC pause (young) 448M->450M(2814M), 0.1219090 secs]<br>
[GC pause (young) 574M->577M(3064M), 0.1778062 secs]<br>
[GC pause (young) 712M->715M(3264M), 0.1878443 secs]<br>
CPU Load Is -1.0<br>
<br>
Start<br>
Stop<br>
Sleep<br>
CPU Load Is 0.9196154547182949<br>
<br>
Start<br>
Stop<br>
Sleep<br>
CPU Load Is 0.9150735995043818<br>
<br>
...<br>
<br>
<br>
<br>
When run with VM args "-XX:+UseParallelGC -verbose:gc"<br>
I get output like this:<br>
<br>
[GC 65536K->64198K(249344K), 0.0628289 secs]<br>
[GC 129734K->127974K(314880K), 0.1583369 secs]<br>
[Full GC 127974K->127630K(451072K), 0.9675224 secs]<br>
[GC 258702K->259102K(451072K), 0.3543645 secs]<br>
[Full GC 259102K->258701K(732672K), 1.8085702 secs]<br>
[GC 389773K->390181K(790528K), 0.3332060 secs]<br>
[GC 579109K->579717K(803328K), 0.5126388 secs]<br>
[Full GC 579717K->578698K(1300480K), 4.0647303 secs]<br>
[GC 780426K->780842K(1567232K), 0.4364933 secs]<br>
CPU Load Is -1.0<br>
<br>
Start<br>
Stop<br>
Sleep<br>
CPU Load Is 0.03137771539054431<br>
<br>
Start<br>
Stop<br>
Sleep<br>
CPU Load Is 0.032351299224373145<br>
<br>
...<br>
<br>
<br>
<br>
When run with VM args "-verbose:gc" I get output like<br>
this:<br>
<br>
[GC 69312K->67824K(251136K), 0.1533803 secs]<br>
[GC 137136K->135015K(251136K), 0.0970460 secs]<br>
[GC 137245K(251136K), 0.0095245 secs]<br>
[GC 204327K->204326K(274368K), 0.1056259 secs]<br>
[GC 273638K->273636K(343680K), 0.1081515 secs]<br>
[GC 342948K->342946K(412992K), 0.1181966 secs]<br>
[GC 412258K->412257K(482304K), 0.1126966 secs]<br>
[GC 481569K->481568K(551808K), 0.1156015 secs]<br>
[GC 550880K->550878K(620928K), 0.1184089 secs]<br>
[GC 620190K->620189K(690048K), 0.1209312 secs]<br>
[GC 689501K->689499K(759552K), 0.1199338 secs]<br>
[GC 758811K->758809K(828864K), 0.1162532 secs]<br>
CPU Load Is -1.0<br>
<br>
Start<br>
Stop<br>
Sleep<br>
CPU Load Is 0.10791719146608299<br>
<br>
Start<br>
[GC 821213K(828864K), 0.1966807 secs]<br>
Stop<br>
Sleep<br>
CPU Load Is 0.1540065314146181<br>
<br>
Start<br>
Stop<br>
Sleep<br>
[GC 821213K(1328240K), 0.1962688 secs]<br>
CPU Load Is 0.08427292195744103<br>
<br>
...<br>
<br>
<br>
<br>
Why is the G1 garbage collector consuming so much CPU<br>
time? Is it stuck in the mark phase as I am modifying<br>
the graph structure?<br>
<br>
I'm not a subscriber to the list, so please CC me in<br>
any response.<br>
<br>
Thanks,<br>
Peter.<br>
<br>
--<br>
<br>
import java.lang.management.<u></u>ManagementFactory;<br>
import com.sun.management.<u></u>OperatingSystemMXBean;<br>
import java.util.Random;<br>
<br>
@SuppressWarnings("<u></u>restriction")<br>
public class Node {<br>
private static OperatingSystemMXBean os =<br>
(OperatingSystemMXBean)<br>
ManagementFactory.<u></u>getOperatingSystemMXBean();<br>
<br>
private Node next;<br>
<br>
private Node[] others = new Node[10];<br>
<br>
public static void main(String[] args) throws<br>
InterruptedException {<br>
<br>
// Build a graph of Nodes<br>
Node head = buildGraph();<br>
<br>
while (true) {<br>
// Print CPU load for this process<br>
System.out.println("CPU Load Is " +<br>
os.getProcessCpuLoad());<br>
System.out.println();<br>
<br>
// Modify the graph<br>
System.out.println("Start");<br>
head = modifyGraph(head);<br>
System.out.println("Stop");<br>
<br>
// Sleep, as otherwise we tend to DoS the host computer...<br>
System.out.println("Sleep");<br>
Thread.sleep(1000);<br>
}<br>
}<br>
<br>
private static Node buildGraph() {<br>
<br>
// Create a collection of Node objects<br>
Node[] array = new Node[10000000];<br>
for (int i = 0; i < array.length; i++) {<br>
array[i] = new Node();<br>
}<br>
<br>
// Each Node refers to 10 other random Nodes<br>
Random random = new Random(12);<br>
for (int i = 0; i < array.length; i++) {<br>
for (int j = 0; j < array[i].others.length; j++) {<br>
int k = random.nextInt(array.length);<br>
array[i].others[j] = array[k];<br>
}<br>
}<br>
<br>
// The first Node serves as the head of a queue<br>
return array[0];<br>
}<br>
<br>
private static Node modifyGraph(Node head) {<br>
<br>
// Perform a million iterations<br>
for (int i = 0; i < 1000000; i++) {<br>
<br>
// Pop a Node off the head of the queue<br>
Node node = head;<br>
head = node.next;<br>
node.next = null;<br>
<br>
// Add the other Nodes to the head of the queue<br>
for (Node other : node.others) {<br>
other.next = head;<br>
head = other;<br>
}<br>
}<br>
return head;<br>
}<br>
<br>
}<br>
<br></div></div>
-- *Actenum Corporation*<br>
Peter Harvey | Cell: <a href="tel:780.729.8192" value="+17807298192" target="_blank">780.729.8192</a> <tel:<a href="tel:780.729.8192" value="+17807298192" target="_blank">780.729.8192</a>><br>
| <a href="mailto:harvey@actenum.com" target="_blank">harvey@actenum.com</a> <mailto:<a href="mailto:harvey@actenum.com" target="_blank">harvey@actenum.com</a>> |<br>
<a href="http://www.actenum.com" target="_blank">www.actenum.com</a> <<a href="http://www.actenum.com" target="_blank">http://www.actenum.com</a>><br>
<br>
<br>
<br>
<br>
-- *Actenum Corporation*<br>
Peter Harvey | Cell: <a href="tel:780.729.8192" value="+17807298192" target="_blank">780.729.8192</a> <tel:<a href="tel:780.729.8192" value="+17807298192" target="_blank">780.729.8192</a>> |<br>
<a href="mailto:harvey@actenum.com" target="_blank">harvey@actenum.com</a> <mailto:<a href="mailto:harvey@actenum.com" target="_blank">harvey@actenum.com</a>> |<br>
<a href="http://www.actenum.com" target="_blank">www.actenum.com</a> <<a href="http://www.actenum.com" target="_blank">http://www.actenum.com</a>><br>
<br>
<br>
<br>
<br>
<br><span class="HOEnZb"><font color="#888888">
<br>
-- <br>
*Actenum Corporation*<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> <mailto:<a href="mailto:harvey@actenum.com" target="_blank">harvey@actenum.com</a>> | <a href="http://www.actenum.com" target="_blank">www.actenum.com</a> <<a href="http://www.actenum.com" target="_blank">http://www.actenum.com</a>><br>
</font></span></blockquote>
<br>
</blockquote></div><br><br clear="all"><div><br></div>-- <br><b>Actenum Corporation</b><br>Peter Harvey | Cell: 780.729.8192 | <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>
</body></html>