• Post Reply
  • Bookmark Topic Watch Topic
  • New Topic

24 Seconds for Garbage Collection - Please help!!!

 
Charles Beam
Greenhorn
Posts: 3
  • 0
  • Mark post as helpful
  • send pies
  • Quote
  • Report post to moderator
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
cbeam1@yahoo.com
 
Jim Yingst
Wanderer
Sheriff
Posts: 18671
  • 0
  • Mark post as helpful
  • send pies
  • Quote
  • Report post to moderator
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
Greenhorn
Posts: 3
  • 0
  • Mark post as helpful
  • send pies
  • Quote
  • Report post to moderator
We have added the -XX:+CMSIncrementalMode flag and removed the -Xnoclassgc flag. Is the -XX:+CMSIncrementalMode equivalent to +Xincgc?

Thanks!!!
Chuck
 
Jim Yingst
Wanderer
Sheriff
Posts: 18671
  • 0
  • Mark post as helpful
  • send pies
  • Quote
  • Report post to moderator
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
Greenhorn
Posts: 3
  • 0
  • Mark post as helpful
  • send pies
  • Quote
  • Report post to moderator
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
  • Post Reply
  • Bookmark Topic Watch Topic
  • New Topic