Ergonomics resizes young generation too small

[Raman Gupta]

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
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/x-pkcs7-signature
Size: 3528 bytes
Desc: S/MIME Cryptographic Signature
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20080820/fc23f675/smime.p7s>