Long remark due to young generation occupancy
Jon Masamitsu
jon.masamitsu at oracle.com
Wed Jan 15 17:22:00 PST 2014
On 1/15/2014 11:41 AM, Gustav Åkesson wrote:
> Hi Jon,
>
> Thanks for looking into this.
>
> A clarification for "Wait up to 30 seconds for the remark to be
> scheduled after a young collection":
> Is this really the case? Is this timeout used after a young
> collection? I was under the impression that
> CMSMaxAbortablePrecleanTime precleans and waits for a young
> collection, and if one occurs (or timeout) the remark is scheduled.
> Here we wait for 30 seconds to a young to happen. Right..?
I think it is
1) concurrent marking runs
2) concurrent precleaning runs
3) concurrent abortable precleaning runs until the remark can
be scheduled or the timeout is reached With CMSMaxAbortablePrecleanTime
set to 30000, the
abortable precleaning runs for 30 seconds unless aborted. Scheduling the
remark means
waiting for the next young collection to empty eden and then
waiting for allocations to fill up eden to the
CMSScheduleRemarkEdenPenetration
percentage. When CMSScheduleRemarkEdenPenetration is
reached abortable precleaning is aborted.
4) remark runs
>
> The work for remark is to revisit updated objects and trace from
> roots again (missing something? ah, and reference processing, but that
> is practically no overhead for us). What is usually the biggest cost
> of the remark? To scan the dirty cards or to trace from roots? Perhaps
> this depends on the application - you're talking about "not always the
> case". What do you refer to? If we have en empty young generation,
> what could bring the remark phase to e.g. 200ms on a high-end server
> like ours?
There could be thousands of thread stacks to scan. Some applications
make heavy
use of soft References. Class unloading happens at remark. The young
gen is not
necessarily empty after a young collection. Some applications make good
use of the
survivor spaces.
>
> For my application, it seems that it tracing from roots that is the
> most expensive. In such scenario, spreading the pause seems as
> beneficial as not running a young collection prior to initial mark
> (which is highly dependent on occupancy in young). Especially since
> young collection is so fast, at least for us.
>
> Regarding the last section that we wait a long time for sweeping -
> does this really matter? Yes, we have a lot of floating garbage in
> case young collections are infrequent and we keep on precleaning, but
> that also means no promotions. The garbage is just sitting there on
> the heap taking space, but no one is claiming that space until a young
> collection. And by then the sweeping proceeds. Or am I missing something?
Some applications can be easily scaled up to the point where the
allocation rate (and promotion rate because of their object lifetimes)
exceeds the rate at which CMS can collect. Such applications sometimes
are run with very little excess space in the heap and any delay in
any part of the CMS collection can mean CMS loses the race and
falls back to a full collection. That's all I'm saying. If you're not
in that situation, don't worry about it.
Jon
>
>
> Best Regards,
>
> Gustav Åkesson
>
>
>
>
>
>
> On Wed, Jan 15, 2014 at 7:24 PM, Jon Masamitsu
> <jon.masamitsu at oracle.com <mailto:jon.masamitsu at oracle.com>> wrote:
>
>> -XX:CMSScheduleRemarkEdenPenetration=0
> Schedule the remark pause immediately after the
> next young collection.
>> -XX:CMSScheduleRemarkEdenSizeThreshold=0
> Any sized eden should allow scheduling of the remark
> pause. That is, no eden is too small to schedule.
>> -XX:CMSMaxAbortablePrecleanTime=30000
> Wait up to 30 seconds for the remark to be scheduled
> after a young collection. Otherwise, wait only up to
> the default of 5 seconds.
>
>
>> So, to the question - is there any obvious drawbacks with the
>> three settings above? Why does eden have to be 50% (default) in
>> order for a remark to be scheduled (besides spreading the pause)?
>> It does only seem to do harm. Any reason?
>
> The default is 50% to try and place the remark pause between two
> young pauses
> (spread it out as you say). I don't believe it is always the
> case that the remark
> pause is very small if it is scheduled immediately after a young
> collection. In
> such cases we still want to spread out the pauses.
>
> If the remark is delayed to wait for the next young collection,
> the sweeping is also delayed. You're not using up space in the
> CMS (tenured) generation but you're also not collecting garbage
> and not making additional space available for reuse (which the
> concurrent sweep does).
>
> Jon
>
>
> On 01/13/2014 02:50 AM, Gustav Åkesson wrote:
>> Hi,
>> This is a topic which has been discussed before, but I think I
>> have some new findings. We're experiencing problems with CMS pauses.
>> Settings we are using.
>> -XX:+UseConcMarkSweepGC
>> -XX:CMSInitiatingOccupancyFraction=68
>> -XX:MaxTenuringThreshold=0
>> -XX:+UseParNewGC
>> -XX:+ScavengeBeforeFullGC
>> -XX:CMSWaitDuration=30000
>> -Xmx2048M
>> -Xms2048M
>> -Xmn1024M
>> Note that MaxTenuringThreshold is 0. This is only done during
>> test to provoke the CMS to run more frequently (otherwise it runs
>> once every day...). Due to this, promotion to old generation is
>> around 400K to 1M per second.
>> We have an allocation rate of roughly 1G per second, meaning that
>> YGC runs once every second.
>> We're running JDK7u17.
>> This is a log entry when running with above settings. This entry
>> is the typical example to all of the CMS collections in this test.
>> *2014-01-13T09:31:52.504+0100: 661.675: [GC [1 CMS-initial-mark:
>> 524986K(1048576K)] 526507K(2096192K), 0.0023550 secs] [Times:
>> user=0.00 sys=0.00, real=0.01 secs]
>> *2014-01-13T09:31:52.506+0100: 661.677: [CMS-concurrent-mark-start]
>> 2014-01-13T09:31:52.644+0100: 661.815: [CMS-concurrent-mark:
>> 0.138/0.138 secs] [Times: user=1.96 sys=0.11, real=0.13 secs]
>> 2014-01-13T09:31:52.644+0100: 661.815:
>> [CMS-concurrent-preclean-start]
>> 2014-01-13T09:31:52.655+0100: 661.826: [CMS-concurrent-preclean:
>> 0.010/0.011 secs] [Times: user=0.14 sys=0.02, real=0.02 secs]
>> 2014-01-13T09:31:52.655+0100: 661.826:
>> [CMS-concurrent-abortable-preclean-start]
>> 2014-01-13T09:31:53.584+0100: 662.755: [GC 662.755: [ParNew
>> Desired survivor size 491520 bytes, new threshold 0 (max 0)
>> : 1046656K->0K(1047616K), 0.0039870 secs]
>> 1571642K->525579K(2096192K), 0.0043310 secs] [Times: user=0.04
>> sys=0.00, real=0.01 secs]
>> 2014-01-13T09:31:54.146+0100: 663.317:
>> [CMS-concurrent-abortable-preclean: 0.831/1.491 secs] [Times:
>> user=16.76 sys=1.54, real=1.49 secs]
>> *2014-01-13T09:31:54.148+0100: 663.319: [GC[YG occupancy: 552670
>> K (1047616 K)]663.319: [Rescan (parallel) , 0.2000060
>> secs]663.519: [weak refs processing, 0.0008740 secs]663.520:
>> [scrub string table, 0.0006940 secs] [1 CMS-remark:
>> 525579K(1048576K)] 1078249K(2096192K), 0.2017690 secs] [Times:
>> user=3.53 sys=0.01, real=0.20 secs]
>> *2014-01-13T09:31:54.350+0100: 663.521: [CMS-concurrent-sweep-start]
>> 2014-01-13T09:31:54.846+0100: 664.017: [GC 664.017: [ParNew
>> Desired survivor size 491520 bytes, new threshold 0 (max 0)
>> : 1046656K->0K(1047616K), 0.0033500 secs]
>> 1330075K->284041K(2096192K), 0.0034660 secs] [Times: user=0.04
>> sys=0.00, real=0.00 secs]
>> 2014-01-13T09:31:55.020+0100: 664.191: [CMS-concurrent-sweep:
>> 0.665/0.670 secs] [Times: user=7.77 sys=0.71, real=0.67 secs]
>> 2014-01-13T09:31:55.020+0100: 664.191: [CMS-concurrent-reset-start]
>> 2014-01-13T09:31:55.023+0100: 664.194: [CMS-concurrent-reset:
>> 0.003/0.003 secs] [Times: user=0.03 sys=0.00, real=0.00 secs]
>> The initial pause is fine. Then I investigated how to reduce the
>> remark phase, and activated -XX:+CMSScavengeBeforeRemark. That
>> flag partly solves this issue (not active in the log above), but
>> I've seen cases when it does not scavenge (I suspect JNI critical
>> section), which is bad and generates yet again long remark pause.
>> And yet again the pause is correlated towards the occupancy in young.
>> So instead, I tried setting...
>> -XX:CMSScheduleRemarkEdenPenetration=0
>> -XX:CMSScheduleRemarkEdenSizeThreshold=0
>> This is a log entry with the settings at the top plus the two
>> above...
>> *2014-01-13T10:18:25.757+0100: 590.198: [GC [1 CMS-initial-mark:
>> 524654K(1048576K)] 526646K(2096192K), 0.0029130 secs] [Times:
>> user=0.00 sys=0.00, real=0.01 secs]
>> *2014-01-13T10:18:25.760+0100: 590.201: [CMS-concurrent-mark-start]
>> 2014-01-13T10:18:25.904+0100: 590.345: [CMS-concurrent-mark:
>> 0.144/0.144 secs] [Times: user=1.98 sys=0.15, real=0.14 secs]
>> 2014-01-13T10:18:25.904+0100: 590.346:
>> [CMS-concurrent-preclean-start]
>> 2014-01-13T10:18:25.912+0100: 590.354: [CMS-concurrent-preclean:
>> 0.008/0.008 secs] [Times: user=0.11 sys=0.00, real=0.01 secs]
>> 2014-01-13T10:18:25.912+0100: 590.354:
>> [CMS-concurrent-abortable-preclean-start]
>> 2014-01-13T10:18:26.836+0100: 591.278: [GC 591.278: [ParNew
>> Desired survivor size 491520 bytes, new threshold 0 (max 0)
>> : 1046656K->0K(1047616K), 0.0048160 secs]
>> 1571310K->525477K(2096192K), 0.0049240 secs] [Times: user=0.05
>> sys=0.00, real=0.01 secs]
>> 2014-01-13T10:18:26.842+0100: 591.283:
>> [CMS-concurrent-abortable-preclean: 0.608/0.929 secs] [Times:
>> user=10.77 sys=0.97, real=0.93 secs]
>> *2014-01-13T10:18:26.843+0100: 591.285: [GC[YG occupancy: 20938 K
>> (1047616 K)]591.285: [Rescan (parallel) , 0.0024770 secs]591.287:
>> [weak refs processing, 0.0007760 secs]591.288: [scrub string
>> table, 0.0006440 secs] [1 CMS-remark: 525477K(1048576K)]
>> 546415K(2096192K), 0.0040480 secs] [Times: user=0.03 sys=0.00,
>> real=0.00 secs]
>> *2014-01-13T10:18:26.848+0100: 591.289: [CMS-concurrent-sweep-start]
>> 2014-01-13T10:18:27.573+0100: 592.015: [CMS-concurrent-sweep:
>> 0.726/0.726 secs] [Times: user=8.50 sys=0.76, real=0.73 secs]
>> 2014-01-13T10:18:27.573+0100: 592.015: [CMS-concurrent-reset-start]
>> 2014-01-13T10:18:27.576+0100: 592.017: [CMS-concurrent-reset:
>> 0.003/0.003 secs] [Times: user=0.03 sys=0.01, real=0.00 secs]
>> This means that when I set these two, CMS STWs go from ~200ms to
>> below 10ms.
>> I'm leaning towards activating...
>> -XX:CMSScheduleRemarkEdenPenetration=0
>> -XX:CMSScheduleRemarkEdenSizeThreshold=0
>> -XX:CMSMaxAbortablePrecleanTime=30000
>> What I have seen with these flags is that as soon as a young is
>> completely collected during abortable preclean, the remark is
>> scheduled and since it can start when eden is nearly empty, it is
>> ridicously fast. In case it takes a long time for preclean to
>> catch a young collection, it is also fine because no promotion is
>> being made. We can live with the pause of young plus a
>> consecutive remark (for us, young is ~10ms).
>> So, to the question - is there any obvious drawbacks with the
>> three settings above? Why does eden have to be 50% (default) in
>> order for a remark to be scheduled (besides spreading the pause)?
>> It does only seem to do harm. Any reason?
>> -XX:+CMSScavengeBeforeRemark I'm thinking to avoid since it can't
>> be completely trusted. Usually it helps, but that is not good
>> enough since the pauses get irregular in case it fails. And with
>> these settings above, it will only add to the CMS pause.
>> Best Regards,
>> Gustav Åkesson
>>
>>
>> _______________________________________________
>> hotspot-gc-use mailing list
>> hotspot-gc-use at openjdk.java.net <mailto:hotspot-gc-use at openjdk.java.net>
>> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>
>
> _______________________________________________
> hotspot-gc-use mailing list
> hotspot-gc-use at openjdk.java.net
> <mailto: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/20140115/be0a04ce/attachment.html
More information about the hotspot-gc-use
mailing list