G1 GC - pauses much larger than target
Chi Ho Kwok
chkwok at digibites.nl
Fri Feb 21 11:33:08 PST 2014
Are you running on Linux? Rarely touched pages get swapped out
aggressively, try setting vm.swappiness to 0 and check sar -B for disk page
in/out stats.
On 21 Feb 2014 20:28, "Kirti Teja Rao" <kirtiteja at gmail.com> wrote:
> 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
>>
>>
>>
>
>
> _______________________________________________
> hotspot-gc-use mailing list
> hotspot-gc-use at openjdk.java.net
> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20140221/a010f775/attachment-0001.html
More information about the hotspot-gc-use
mailing list