Ergonomics resizes young generation too small

[Raman Gupta]

Thanks for your comments Jon.

If I recall correctly, full collection pauses were 3-5 seconds, both
before and after the JVM resized the young generation.

I can't run this particular app on 1.6 yet, but will definitely start
using the AdaptiveSizePolicyOutputInterval flag on my 1.6 apps.

I will set the minimum size for the young generation to avoid this
problem in my 1.5 apps.

Cheers,
Raman

Jon Masamitsu wrote:
> How large are your full collection pauses?
> 
> Can you rerun this test with jdk6 and add the
> flag -XX:AdaptiveSizePolicyOutputInterval=1?
> That will output information about the
> ergonomics decision at each GC.
> 
> The simplest way to avoid this problem is to set
> a minimum young gen size on the command
> line.  -XX:NewSize=<minimum size>
> 
> 
> Raman Gupta wrote On 08/20/08 13:22,:
> 
>> I am using GC ergonomics on JDK 1.5.0_12 32-bit on Sun Solaris Sparc, command line:
>>
>> -server -Xms1g -Xmx1g -XX:+DisableExplicitGC -XX:NewRatio=2 -XX:+UseParallelGC -XX:MaxGCPauseMillis=35 -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime
>>
>> It appears that over time the JVM is making the young generation smaller and smaller, to the point where the JVM is doing almost continuous garbage collections.
>>
>> Here is a snippet from my GC output, skipping the application initialization phase:
>>
>> 134.522: [GC [PSYoungGen: 131536K->320K(130496K)] 159347K->28363K(829568K), 0.0126834 secs]
>> Total time for which application threads were stopped: 0.0138235 seconds
>> Application time: 1.9330309 seconds
>> 137.474: [GC [PSYoungGen: 130496K->318K(138688K)] 158539K->28594K(837760K), 0.0123787 secs]
>> Total time for which application threads were stopped: 0.0135995 seconds
>> Application time: 0.8795206 seconds
>> 140.401: [GC [PSYoungGen: 129534K->256K(128512K)] 157810K->28790K(827584K), 0.0133409 secs]
>> Total time for which application threads were stopped: 0.0145290 seconds
>> Application time: 3.3926780 seconds
>> 143.808: [GC [PSYoungGen: 128512K->320K(135360K)] 157046K->29058K(834432K), 0.0117748 secs]
>> Total time for which application threads were stopped: 0.0130701 seconds
>> Application time: 1.3970241 seconds
>> 147.254: [GC [PSYoungGen: 127616K->304K(126656K)] 156354K->29274K(825728K), 0.0116910 secs]
>> Total time for which application threads were stopped: 0.0128008 seconds
>> Application time: 2.9351317 seconds
>> 150.203: [GC [PSYoungGen: 126640K->288K(132352K)] 155610K->29490K(831424K), 0.0114801 secs]
>> Total time for which application threads were stopped: 0.0126512 seconds
>> Application time: 3.5357540 seconds
>> 153.751: [GC [PSYoungGen: 125664K->320K(124800K)] 154866K->29762K(823872K), 0.0117090 secs]
>> Total time for which application threads were stopped: 0.0128397 seconds
>> Application time: 1.1165393 seconds
>> 157.088: [GC [PSYoungGen: 124800K->304K(129472K)] 154242K->29978K(828544K), 0.0251655 secs]
>> Total time for which application threads were stopped: 0.0262839 seconds
>> Application time: 0.0840740 seconds
>> 160.448: [GC [PSYoungGen: 123888K->384K(123072K)] 153562K->30282K(822144K), 0.0117038 secs]
>>
>> So far so good, the system still has a reasonable eden size and is easily meeting the MAX GC pause time goal. But for some reason, from this point forward, the system continues to make the young generation smaller and smaller, finally resulting in:
>>
>> 12392.994: [GC [PSYoungGen: 1552K->181K(1728K)] 365538K->364388K(700800K), 0.0271502 secs]
>> Total time for which application threads were stopped: 0.0278218 seconds
>> Application time: 0.1166776 seconds
>> 12393.139: [GC [PSYoungGen: 1525K->16K(1728K)] 365732K->364376K(700800K), 0.0281370 secs]
>> Total time for which application threads were stopped: 0.0287963 seconds
>> Application time: 0.1309121 seconds
>> 12393.300: [GC [PSYoungGen: 1360K->16K(1728K)] 365720K->364376K(700800K), 0.0503697 secs]
>> Total time for which application threads were stopped: 0.0527805 seconds
>> Application time: 0.2960570 seconds
>> 12393.648: [GC [PSYoungGen: 1360K->64K(1728K)] 365720K->364424K(700800K), 0.0336176 secs]
>> Total time for which application threads were stopped: 0.0350546 seconds
>> Application time: 0.3747399 seconds
>> 12394.059: [GC [PSYoungGen: 1408K->80K(1728K)] 365768K->364452K(700800K), 0.0318642 secs]
>> Total time for which application threads were stopped: 0.0346854 seconds
>> Application time: 0.4696706 seconds
>> 12394.564: [GC [PSYoungGen: 1424K->112K(1728K)] 365796K->364508K(700800K), 0.0288190 secs]
>> Total time for which application threads were stopped: 0.0315647 seconds
>> Application time: 0.0420326 seconds
>> 12394.636: [GC [PSYoungGen: 1456K->304K(1728K)] 365852K->364740K(700800K), 0.0347478 secs]
>> Total time for which application threads were stopped: 0.0365562 seconds
>> Application time: 0.0330247 seconds
>> 12394.706: [GC [PSYoungGen: 1648K->304K(1792K)] 366084K->364893K(700864K), 0.0251325 secs]
>> Total time for which application threads were stopped: 0.0263055 seconds
>> Application time: 0.1094829 seconds
>>
>> Ok, the pause time goal is still being met but application time is much lower AND pause times are much higher than they were initially), so this is pretty sub-optimal end-state for the JVM.
>>
>> Do I need to set a higher throughput goal than the default (perhaps 200?) to avoid this pathological behavior?
>>
>> Cheers,
>> Raman Gupta