24 Seconds for Garbage Collection - Please help!!!

[Charles Beam]

We are have a serious problem with garbage collection.

We have a very complex application running on an 8 CPU \ 16gig memory Sun server using Java 1.4.2_9.

The JVM setting are as follows:
"$JAVA_HOME/bin/java" -Xms2148m -Xmx2148m -server -XX:NewRatio=2 -XX ermSize=128m -XX:MaxPermSize=128m -XX:+PrintGCDetails -XX:+DisableExplicitGC -XX:+UseConcMarkSweepGC -XX:NewSize=512m -XX:SurvivorRatio=16 -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCTimeStamps -Xnoclassgc -Djava.util.logging.config.file=/ap/p/cru/v1/appcru/pdom/pcru/staging/logging/logging.properties -Dweblogic.Name=${SERVER_NAME} -Dweblogic.management.username=${WLS_USER} -Dweblogic.management.password=${WLS_PW} -Dweblogic.management.server=${ADMIN_URL} -Djava.security.policy="${WL_HOME}/server/lib/weblogic.policy" weblogic.Server

We are using the Concurrent Mark Sweep Collector.

The incremental collection runs approx. every 5 -15 seconds and last .01 seconds. A major collection is running approx every 5 minutes and is taking approx 24 seconds. During the 24 second major GC, our users are all frozen.

Here is a snapshot of the GC logs:
31692.752: [GC 31692.752: [ParNew: 523392K->0K(523840K), 0.0789173 secs] 1583641K->1068819K(2199104K), 0.0791993 secs]
31700.841: [GC 31700.841: [ParNew: 523392K->0K(523840K), 0.3565117 secs] 1592211K->1101206K(2199104K), 0.3568170 secs]
31703.810: [GC 31703.811: [ParNew: 523392K->0K(523840K), 0.0482865 secs] 1624598K->1110598K(2199104K), 0.0486247 secs]
31711.287: [GC 31711.287: [ParNew: 523392K->0K(523840K), 0.1359422 secs] 1633990K->1140657K(2199104K), 0.1362390 secs]
31711.469: [GC [1 CMS-initial-mark: 1140657K(1675264K)] 1140721K(2199104K), 0.0090538 secs]
31721.063: [CMS-concurrent-mark: 9.583/9.584 secs]
31721.240: [CMS-concurrent-preclean: 0.175/0.177 secs]
31721.304: [GC31721.305: [Rescan (parallel) , 2.9224848 secs]31724.227: [weak refs processing, 0.0518957 secs] [1 CMS-remark: 1140657K(1675264K)] 1500183K(2199104K), 2.9753187 secs]
31726.692: [GC 31726.692: [ParNew: 523392K->0K(523840K), 0.0981620 secs] 1664047K->1148322K(2199104K), 0.0984634 secs]
31730.848: [CMS-concurrent-sweep: 6.366/6.568 secs]
31731.078: [CMS-concurrent-reset: 0.229/0.229 secs]
31732.737: [GC 31732.737: [ParNew: 523392K->523392K(523840K), 0.0000837 secs]31732.737: [CMS: 844493K->834171K(1675264K), 19.4416439 secs] 1367885K->834171K(2199104K), 19.4421517 secs]
31756.384: [GC 31756.384: [ParNew: 523392K->0K(523840K), 0.0950031 secs] 1357563K->844687K(2199104K), 0.0953542 secs]
31764.582: [GC 31764.582: [ParNew: 523392K->0K(523840K), 0.2605353 secs] 1368079K->873371K(2199104K), 0.2608119 secs]
31773.105: [GC 31773.105: [ParNew: 523392K->0K(523840K), 0.4328396 secs] 1396763K->918659K(2199104K), 0.4331518 secs]
31776.049: [GC 31776.049: [ParNew: 523392K->0K(523840K), 0.0479186 secs] 1442051K->927357K(2199104K), 0.0482106 secs]


Any help you can provide would be most appreciated!!!

Chuck
[e-mail]

[Jim Yingst]

Have you seen this FAQ entry and Tuning Garbage Collection with the 1.4.2 Java Virtual Machine? From your problem description, the first thing I'd try is replacing -XX:+UseConcMarkSweepGC with +Xincgc, then try the other options from the FAQ entry.
[ May 09, 2007: Message edited by: Jim Yingst ]

[Charles Beam]

We have added the -XX:+CMSIncrementalMode flag and removed the -Xnoclassgc flag. Is the -XX:+CMSIncrementalMode equivalent to +Xincgc?

Thanks!!!
Chuck

[Jim Yingst]

I don't know - is that even an option for JDK 1.4.2? I got tired of looking for documentation on it. If it is, it sounds like it's either equivalent, or a newer alternative. Try it and find out, I guess.

[Charles Beam]

We are now seeing the ParNew and Concurrent collector run as follows:

27347.263: [GC 27347.263: [ParNew: 523392K->0K(523840K), 0.0667966 secs] 1284623K->767134K(2199104K), 0.0670734 secs]
27348.539: [GC [1 CMS-initial-mark: 767134K(1675264K)] 899572K(2199104K), 0.8718108 secs]
27354.430: [GC 27354.430: [ParNew: 523392K->0K(523840K), 0.1109239 secs] 1290526K->777364K(2199104K), 0.1112427 secs]
27378.326: [GC 27378.326: [ParNew: 523392K->0K(523840K), 0.0515447 secs] 1300756K->785152K(2199104K), 0.0518312 secs]
27389.030: [CMS-concurrent-mark: 10.912/39.619 secs]
27389.994: [CMS-concurrent-preclean: 0.914/0.964 secs]
27389.996: [GC27389.996: [Rescan (parallel) , 2.2856893 secs]27392.282: [weak refs processing, 0.0626480 secs] [1 CMS-remark: 785152K(1675264K)] 1071966K(2199104K), 2.3490792 secs]
27413.471: [GC 27413.472: [ParNew: 523392K->0K(523840K), 0.1226342 secs] 1306898K->795865K(2199104K), 0.1229631 secs]
27416.982: [CMS-concurrent-sweep: 4.622/24.636 secs]
27417.200: [CMS-concurrent-reset: 0.218/0.218 secs]
27432.514: [GC 27432.514: [ParNew: 523392K->0K(523840K), 0.0800121 secs] 1297024K->803520K(2199104K), 0.0802881 secs]

The concurrent-mark and concurrent-preclean appear to be sharing the CPU with the application threads, but the Concurrent Collector is now running every 30 seconds.

We went from a 24 second pause every 5 minutes to a 5 second pause every 30 seconds.

Any ideas???

Thanks!!!
Chuck