CMSEdenChunksRecordAlways & CMSParallelInitialMarkEnabled

Thu Jun 19 03:19:48 UTC 2014

The options are working great and as expected (faster initial mark, and no long pauses after abortable preclean timeout). One weird thing though which I’m curious about: I’m showing some data for six JVMs (calling them nodes - they are on separate machines)

all with :

Linux version 2.6.32-431.3.1.el6.x86_64 (mockbuild at c6b10.bsys.dev.centos.org) (gcc version 4.4.7 20120313 (Red Hat 4.4.7-4) (GCC) ) #1 SMP Fri Jan 3 21:39:27 UTC 2014
JDK 1.7.0_60-b19
16 gig old gen
8 gig new (6.4 gig eden)
-XX:+UseParNewGC
-XX:+UseConcMarkSweepGC
-XX:+CMSParallelRemarkEnabled
256 gig RAM
16 cores (sandy bridge)

Nodes 4-6 also have 

-XX:+CMSEdenChunksRecordAlways
-XX:+CMSParallelInitialMarkEnabled

There are some application level config differences (which limit amount of certain objects kept in memory before flushing to disk) - 1&4 have the same app config, 2&5 have the same app config, 3&6 have the same app config

This first dump, shows two days worth of total times application threads were stopped via grepping logs for Total time for which application threads were stopped and summing the values. worst case 4 minutes over the day is not too bad, so this isn’t a big issue

2014-06-17 : 1 154.623
2014-06-17 : 2 90.3006
2014-06-17 : 3 75.3602
2014-06-17 : 4 180.618
2014-06-17 : 5 107.668
2014-06-17 : 6 99.7783
-------
2014-06-18 : 1 190.741
2014-06-18 : 2 82.8865
2014-06-18 : 3 90.0098
2014-06-18 : 4 239.702
2014-06-18 : 5 149.332
2014-06-18 : 6 138.03

Notably however if you look via JMX/visualGC, the total GC time is actually lower on nodes 4 to 6 than the equivalent nodes 1 to 3. Now I know that biased lock revocation and other things cause safe point, so I figure something other than GC must be the cause… so I just did a count of log lines with  Total time for which application threads were stopped and got this:

2014-06-17 : 1 19282
2014-06-17 : 2 6784
2014-06-17 : 3 1275
2014-06-17 : 4 26356
2014-06-17 : 5 14491
2014-06-17 : 6 8402
-------
2014-06-18 : 1 20943
2014-06-18 : 2 1134
2014-06-18 : 3 1129
2014-06-18 : 4 30289
2014-06-18 : 5 16508
2014-06-18 : 6 11459

I can’t cycle these nodes right now (to try each new parameter individually), but am curious whether you can think of why adding these parameters would have such a large effect on the number of safe point stops - e.g. 1129 vs 11459 for otherwise identically configured nodes with very similar workload. Note the ratio is highest on nodes 2 vs node 5 which spill the least into the old generation (so certainly fewer CMS cycles, and also fewer young gen collections) if that sparks any ideas.

Thanks,

Graham.

P.S. It is entirely possible I don’t know exactly what Total time for which application threads were stopped refers to in all cases (I’m assuming it is a safe point stop)

On Jun 16, 2014, at 1:54 PM, graham sanderson <graham at vast.com> wrote:

> Thanks Jon; that’s exactly what i was hoping
> 
> On Jun 16, 2014, at 1:27 PM, Jon Masamitsu <jon.masamitsu at oracle.com> wrote:
> 
>> 
>> On 06/12/2014 09:16 PM, graham sanderson wrote:
>>> Hi, I hope this is the right list for this question:
>>> 
>>> I was investigating abortable preclean timeouts in our app (and associated long remark pause) so had a look at the old jdk6 code I had on my box, wondered about recording eden chunks during certain eden slow allocation paths (I wasn’t sure if TLAB allocation is just a CAS bump), and saw what looked perfect in the latest code, so was excited to install 1.7.0_60-b19
>>> 
>>> I wanted to ask what you consider the stability of these two options to be (I’m pretty sure at least the first one is new in this release)
>>> 
>>> I have just installed locally on my mac, and am aware of http://bugs.java.com/bugdatabase/view_bug.do?bug_id=8021809 which I could reproduce, however I wasn’t able to reproduce it without -XX:-UseCMSCompactAtFullCollection (is this
>>>           your understanding too?)
>> 
>> Yes.
>> 
>>> 
>>> We are running our application with 8 gig young generation (6.4g eden), on boxes with 32 cores… so parallelism is good for short pauses
>>> 
>>> we already have
>>> 
>>> -XX:+UseParNewGC 
>>> -XX:+UseConcMarkSweepGC
>>> -XX:+CMSParallelRemarkEnabled
>>> 
>>> we have seen a few long(isn) initial marks, so 
>>> 
>>> -XX:+CMSParallelInitialMarkEnabled sounds good
>>> 
>>> as for 
>>> 
>>> -XX:+CMSEdenChunksRecordAlways
>>> 
>>> my question is: what constitutes a slow path such an eden chunk is potentially recorded… TLAB allocation, or more horrific things; basically (and I’ll test our app with -XX:+CMSPrintEdenSurvivorChunks) is it likely that I’ll actually get less samples using -XX:+CMSEdenChunksRecordAlways in a highly multithread app than I would with sampling, or put another way… what sort of app allocation patterns if any might avoid the slow path altogether and might leave me with just one chunk?
>> 
>> Fast path allocation is done from TLAB's.  If you have to get
>> a new TLAB, the call to get the new TLAB comes from compiled
>> code but the call is into the JVM and  that is the slow path where
>> the sampling is done.
>> 
>> Jon
>> 
>>> 
>>> Thanks,
>>> 
>>> Graham
>>> 
>>> P.S. less relevant I think, but our old generation is 16g
>>> P.P.S. I suspect the abortable preclean timeouts mostly happen after a burst of very high allocation rate followed by an almost complete lull… this is one of the patterns that can happen in our application
>> 
> 

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20140618/00706484/attachment.htm>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 1574 bytes
Desc: not available
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20140618/00706484/smime.p7s>