G1 GC - pauses much larger than target
Kirti Teja Rao
kirtiteja at gmail.com
Fri Feb 21 11:27:38 PST 2014
Hi,
@Jenny - CPU looks fine. Never over 40% and generally between 25-35%. Some
of these pauses are as large as 1 second and these are always observed
after the parallel phase, I assume this is the phase were G1 would need the
most amount of CPU.
@Andreas - Most of these pauses are in young collection and are not showing
in the parallel/serial phases shown in GC log. The pauses i observe are
unreasonable 1.5+ sec for a heap of 2 GB.
@All - [Times: user=0.06 sys=0.00, real=1.54 secs] real time being far
greater than user time, I believe G1 is blocked on some resource. The
application i run is not swapping and also there is more headroom in
memory. CPU is less than 35%.There are other applications running on the
machine which log quite a bit and can cause the iowait avg queue size to
spike upto 20-30 occasionally. Does G1 logging happen during the pause
time? Can a slow disk or high disk IO affect these timings?
Is there anything else that we can try to uncover the cause for these
pauses?
2014-02-21T06:18:13.592+0000: 12675.969: Application time: 10.7438770
seconds
2014-02-21T06:18:13.593+0000: 12675.970: [GC pause (young)
Desired survivor size 81788928 bytes, new threshold 15 (max 15)
- age 1: 564704 bytes, 564704 total
- age 2: 18504 bytes, 583208 total
- age 3: 18552 bytes, 601760 total
- age 4: 18776 bytes, 620536 total
- age 5: 197048 bytes, 817584 total
- age 6: 18712 bytes, 836296 total
- age 7: 18456 bytes, 854752 total
- age 8: 18920 bytes, 873672 total
- age 9: 18456 bytes, 892128 total
- age 10: 18456 bytes, 910584 total
- age 11: 18456 bytes, 929040 total
- age 12: 18456 bytes, 947496 total
- age 13: 18488 bytes, 965984 total
- age 14: 18456 bytes, 984440 total
- age 15: 18456 bytes, 1002896 total
12675.970: [G1Ergonomics (CSet Construction) start choosing CSet,
_pending_cards: 4408, predicted base time: 6.77 ms, remaining time: 23.23
ms, target pause time: 30.00 ms]
12675.970: [G1Ergonomics (CSet Construction) add young regions to CSet,
eden: 306 regions, survivors: 1 regions, predicted young region time: 1.89
ms]
12675.970: [G1Ergonomics (CSet Construction) finish choosing CSet, eden:
306 regions, survivors: 1 regions, old: 0 regions, predicted pause time:
8.67 ms, target pause time: 30.00 ms]
, 0.0079290 secs]
[Parallel Time: 6.0 ms, GC Workers: 9]
[GC Worker Start (ms): Min: 12675970.1, Avg: 12675970.3, Max:
12675970.8, Diff: 0.7]
[Ext Root Scanning (ms): Min: 3.0, Avg: 4.0, Max: 5.0, Diff: 1.9,
Sum: 36.3]
[Update RS (ms): Min: 0.0, Avg: 0.5, Max: 0.9, Diff: 0.9, Sum: 4.1]
[Processed Buffers: Min: 0, Avg: 5.4, Max: 13, Diff: 13, Sum: 49]
[Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.9]
[Object Copy (ms): Min: 0.3, Avg: 0.7, Max: 0.9, Diff: 0.6, Sum: 6.5]
[Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 2.0]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum:
0.2]
[GC Worker Total (ms): Min: 5.1, Avg: 5.6, Max: 5.8, Diff: 0.8, Sum:
50.1]
[GC Worker End (ms): Min: 12675975.8, Avg: 12675975.9, Max:
12675975.9, Diff: 0.1]
[Code Root Fixup: 0.0 ms]
[Clear CT: 0.5 ms]
[Other: 1.4 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.5 ms]
[Ref Enq: 0.0 ms]
[Free CSet: 0.7 ms]
[Eden: 1224.0M(1224.0M)->0.0B(1224.0M) Survivors: 4096.0K->4096.0K Heap:
1342.2M(2048.0M)->118.1M(2048.0M)]
[Times: user=0.06 sys=0.00, real=1.54 secs]
2014-02-21T06:18:15.135+0000: 12677.511: Total time for which application
threads were stopped: 1.5421650 seconds
On Fri, Feb 21, 2014 at 12:38 AM, Andreas Müller <Andreas.Mueller at mgm-tp.com
> wrote:
> Hi Kirti,
>
>
>
> > I am trying out G1 collector for our application. Our application runs
> with 2GB heap and we expect relatively low latency.
>
> > The pause time target is set to 25ms. There >are much bigger pauses (and
> unexplained) in order of few 100s of ms.
>
> > This is not a rare occurence and i can see this 15-20 times in 6-7 hours
> runs.
>
>
>
> This conforms to what I have observed in extended tests:
>
> G1's control of GC pause duration is limited to a rather narrow range.
>
> Even in that range, only new gen pauses do follow the pause time target
> well while "mixed" pauses tend to overshoot with considerable probability.
>
> Find attached a graphic which shows what I mean:
>
> - New gen pauses (red) do follow the target very well from 150-800
> millis
>
> - With a target below 150 the actual new gen pauses remain flat at
> 150-180 millis
>
> - "mixed" pauses (blue) do not follow the target well and some of
> them will always take 500-700 millis, whatever the target be
>
> - There are other pauses (remark etc., green) which are short but
> completely independent of the target value
>
>
>
> The range with reasonable control depends on the heap size, the
> application and the hardware.
>
> I measured the graphic attached on a 6-core Xeon/2GHz server running Java
> 7u45 on CentOS/Linux with 64 GB RAM and a heap size of -Xms50g -Xmx50g.
>
> (For which the pause durations achieved are not bad at all!)
>
> The application was a synthetic benchmark described here:
> http://blog.mgm-tp.com/2013/12/benchmarking-g1-and-other-java-7-garbage-collectors/
>
> With the same benchmark but only 10 GB of overall heap size on a Oracle T3
> server running Java 7u45 on Solaris/SPARC I got a very similar kind of plot
> but the range with reasonable pause time control was now 60-180 millis.
>
> Again the pause durations reached were by themselves not bad at all. But
> the idea of setting a pause time target and expecting it to be followed in
> a meaningful way is to some extent misleading.
>
>
>
> These results on G1's pause time control will be published soon on the
> blog of the link above.
>
>
>
> Best regards
>
> Andreas
>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20140221/e8809310/attachment.html
More information about the hotspot-gc-use
mailing list