Very long young gc pause (ParNew with CMS)

[Kirk Pepperdine]

There is so much stuff in this gc log it's hard to see the real problem... As as much data as there is in the flags, we're missing the trigger for the CMS cycle

That said, these settings will cause premature promotion in most applications. This will put more stress on CMS

>>> -XX:SurvivorRatio=8 \
>>> -XX:TargetSurvivorRatio=90 \


The initiating occupancy fraction is very high IMHO and that will cause more difficulties. In most cases, it's better to have a lower threshold as this will give more head room to sort out fragmentation. Also, new size pinned to 256m is also causing a lot of premature promotion. And -Xmx==-Xms.... you can read one of my blog postings on that subject. I do find it interesting that you have a 28G heap with new size set to 256m.

IMHO, too  much work has been done setting flags. I'd be included to turn most of them back to default settings. I'd turn off most of the data being collected in the GC log as I think it's mostly for debugging GC and it's not very helpful for sizing analysis.

Last point,  the benefit of CMS is shorter pause times and if you're not seeing that, you might be better off with the parallel collector.


Note for the guys I have having the RMI/full gc discussion with...
>>> -Dsun.rmi.dgc.server.gcInterval=9223372036854775807 \
>>> -Dsun.rmi.dgc.client.gcInterval=9223372036854775807 \

You've gotta love these settings... ;And I'll have to say they are quite typical.  8^)

Regards,
Kirk


On 2012-01-09, at 12:48 PM, Florian Binder wrote:

> Hi Kirk,
> 
> I have attached the log since 8:45 am today to this mail.
> Every full hour the application is creating a lot of objects which are kept in memory for a long time. This process may take a few minutes (should be done in less than 10 min) and may explain the premature promotion. But not all young gcs, which are taking so long, are during this process.
> 
> Regards,
> Flo
> 
> 
> Am 09.01.2012 12:23, schrieb Kirk Pepperdine:
>> Can you post the complete log? I see a premature promotion event but you'd need the entire log to see if this is pathological case or just an anomaly.
>> 
>> Regards,
>> Kirk
>> 
>> On 2012-01-09, at 12:08 PM, Florian Binder wrote:
>> 
>>> Hi everybody,
>>> 
>>> I am using CMS (with ParNew) gc and have very long (>  6 seconds) young
>>> gc pauses.
>>> As you can see in the log below the old-gen-heap consists of one large
>>> block, the new Size has 256m, it uses 13 worker threads and it has to
>>> copy 27505761 words (~210mb) directly from eden to old gen.
>>> I have seen that this problem occurs only after about one week of
>>> uptime. Even thought we make a full (compacting) gc every night.
>>> Since real-time>  user-time I assume it might be a synchronization
>>> problem. Can this be true?
>>> 
>>> Do you have any Ideas how I can speed up this gcs?
>>> 
>>> Please let me know, if you need more informations.
>>> 
>>> Thank you,
>>> Flo
>>> 
>>> 
>>> ##### java -version #####
>>> java version "1.6.0_29"
>>> Java(TM) SE Runtime Environment (build 1.6.0_29-b11)
>>> Java HotSpot(TM) 64-Bit Server VM (build 20.4-b02, mixed mode)
>>> 
>>> ##### The startup parameters: #####
>>> -Xms28G -Xmx28G
>>> -XX:+UseConcMarkSweepGC \
>>> -XX:CMSMaxAbortablePrecleanTime=10000 \
>>> -XX:SurvivorRatio=8 \
>>> -XX:TargetSurvivorRatio=90 \
>>> -XX:MaxTenuringThreshold=31 \
>>> -XX:CMSInitiatingOccupancyFraction=80 \
>>> -XX:NewSize=256M \
>>> 
>>> -verbose:gc \
>>> -XX:+PrintFlagsFinal \
>>> -XX:PrintFLSStatistics=1 \
>>> -XX:+PrintGCDetails \
>>> -XX:+PrintGCDateStamps \
>>> -XX:-TraceClassUnloading \
>>> -XX:+PrintGCApplicationConcurrentTime \
>>> -XX:+PrintGCApplicationStoppedTime \
>>> -XX:+PrintTenuringDistribution \
>>> -XX:+CMSClassUnloadingEnabled \
>>> -Dsun.rmi.dgc.server.gcInterval=9223372036854775807 \
>>> -Dsun.rmi.dgc.client.gcInterval=9223372036854775807 \
>>> 
>>> -Djava.awt.headless=true
>>> 
>>> ##### From the out-file (as of +PrintFlagsFinal): #####
>>> ParallelGCThreads                         = 13
>>> 
>>> ##### The gc.log-excerpt: #####
>>> Application time: 20,0617700 seconds
>>> 2011-12-22T12:02:03.289+0100: [GC Before GC:
>>> Statistics for BinaryTreeDictionary:
>>> ------------------------------------
>>> Total Free Space: 1183290963
>>> Max   Chunk Size: 1183290963
>>> Number of Blocks: 1
>>> Av.  Block  Size: 1183290963
>>> Tree      Height: 1
>>> Before GC:
>>> Statistics for BinaryTreeDictionary:
>>> ------------------------------------
>>> Total Free Space: 0
>>> Max   Chunk Size: 0
>>> Number of Blocks: 0
>>> Tree      Height: 0
>>> [ParNew
>>> Desired survivor size 25480392 bytes, new threshold 1 (max 31)
>>> - age   1:   28260160 bytes,   28260160 total
>>> : 249216K->27648K(249216K), 6,1808130 secs]
>>> 20061765K->20056210K(29332480K)After GC:
>>> Statistics for BinaryTreeDictionary:
>>> ------------------------------------
>>> Total Free Space: 1155785202
>>> Max   Chunk Size: 1155785202
>>> Number of Blocks: 1
>>> Av.  Block  Size: 1155785202
>>> Tree      Height: 1
>>> After GC:
>>> Statistics for BinaryTreeDictionary:
>>> ------------------------------------
>>> Total Free Space: 0
>>> Max   Chunk Size: 0
>>> Number of Blocks: 0
>>> Tree      Height: 0
>>> , 6,1809440 secs] [Times: user=3,08 sys=0,51, real=6,18 secs]
>>> Total time for which application threads were stopped: 6,1818730 seconds
>>> _______________________________________________
>>> hotspot-gc-use mailing list
>>> hotspot-gc-use at openjdk.java.net
>>> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
> 
> <gc.log>