Help, full gc takes forever

[Office Consotec]

Hello GC Team, Help!

in our production environment we are facing some
very extensive GC times: 17sec, 70 80 sec etc.

** Enviroment
Java(TM) SE Runtime Environment (build 1.6.0_24-b07),  OS: Windows  XP x64
Memory: 4 GB, Application: Jboss Application Server (Cluster),
Restart: Weekly, Note: No other application installed, just the
application server (JBOss, approx ~1000 threads).

** GC Settings
-server -Xmx1580m -Xms1580m -Xmn800m
-Dsun.rmi.dgc.client.gcInterval=3600000
-Dsun.rmi.dgc.server.gcInterval=3600000
-Xss128k -XX:ThreadStackSize=128 -XX:+UseParallelGC
-XX:+UseParallelOldGC -XX:MaxGCPauseMillis=50
-Xloggc:%ORCA_LOG_DIR%\gc.log
-XX:-UseAdaptiveSizePolicy -XX:SurvivorRatio=6 -XX:PermSize=96m
-XX:MaxPermSize=96m
-XX:+ExplicitGCInvokesConcurrent -XX:ParallelGCThreads=6
-XX:+PrintCommandLineFlags -XX:MaxTenuringThreshold=31

For both examples below I noticed, that the "real time" is much bigger than
the actual used time (user+sys)!
=> [Times: user=2.72 sys=0.08, real=17.25 secs]
=> [Times: user=1.92 sys=0.80, real=80.42 secs]

Can this be wait time for some resource? Memory?
Since the system has only  4GB memory, I consider paging as a potential
problem, but
can paging  explain 80 secs? Any help is appreciated!!!

Thanks!


***  80 Seconds
2012-05-08T23:48:18.232-0600: 283660.832: [Full GC [PSYoungGen:
89592K->0K(627200K)] [ParOldGen: 683926K->238185K(696320K)]
 773518K->238185K(1323520K) [PSPermGen: 75601K->75595K(98304K)], 0.4936415
secs] [Times: user=2.00 sys=0.00, real=0.50 secs]
--
-- A number of young GC
--
2012-05-09T19:28:32.502-0600: 354473.434: [GC [PSYoungGen:
626836K->89594K(627200K)] 1315609K->781407K(1323520K), 0.0625468 secs]
[Times: user=0.42 sys=0.00, real=0.06 secs]
2012-05-09T19:28:32.580-0600: 354473.513: [Full GC [PSYoungGen:
89594K->0K(627200K)] [ParOldGen: 691812K->191497K(696320K)]
781407K->191497K(1323520K) [PSPermGen: 75897K->75600K(98304K)], 80.4223984
secs]
[Times: user=1.92 sys=0.80, real=80.42 secs]
Total time for which application threads were stopped: 80.5050138 seconds


*** 17 Seconds ***
226899.147: [pre compact{Heap before GC invocations=53721 (full 158):
 PSYoungGen      total 716800K, used 713640K [0xb6bf0000, 0xe8bf0000,
0xe8bf0000)
  eden space 614400K, 100% used [0xb6bf0000,0xdc3f0000,0xdc3f0000)
  from space 102400K, 96% used [0xe27f0000,0xe88da1f0,0xe8bf0000)
  to   space 102400K, 99% used [0xdc3f0000,0xe27edab0,0xe27f0000)
 ParOldGen       total 798720K, used 798303K [0x85ff0000, 0xb6bf0000,
0xb6bf0000)
  object space 798720K, 99% used [0x85ff0000,0xb6b87fb0,0xb6bf0000)
 PSPermGen       total 98304K, used 75275K [0x7fff0000, 0x85ff0000,
0x85ff0000)
  object space 98304K, 76% used [0x7fff0000,0x84972e80,0x85ff0000)
, 0.0003759 secs]
2012-01-17T09:52:59.467-0500: 226899.147: [Full GC226899.151: [marking
phase226899.151: [par mark, 0.4889255 secs]
226899.640: [reference processing, 0.0052557 secs]
226899.645: [class unloading, 0.0692870 secs]
, 0.5635781 secs]
226899.714: [summary phase, 5.0144262 secs]
226904.729: [adjust roots, 0.0440449 secs]
226904.773: [compact perm gen, 0.0871871 secs]
226904.860: [compaction phase226904.860: [drain task setup, 0.0003858 secs]
226904.861: [dense prefix task setup, 0.0000069 secs]
226904.861: [steal task setup, 0.0000004 secs]
226904.861: [par compact, 0.2529356 secs]
226905.114: [deferred updates, 0.0085332 secs]
, 0.2621966 secs]
226905.122: [post compact, 11.2590418 secs]
 [PSYoungGen: 713640K->0K(716800K)] [ParOldGen: 798303K->273778K(798720K)]
1511944K->273778K(1515520K) [PSPermGen: 75275K->75270K(98304K)], 17.2345163
secs] [Times: user=2.72 sys=0.08, real=17.25 secs]

Heap after GC invocations=53721 (full 158):
 PSYoungGen      total 716800K, used 0K [0xb6bf0000, 0xe8bf0000, 0xe8bf0000)
  eden space 614400K, 0% used [0xb6bf0000,0xb6bf0000,0xdc3f0000)
  from space 102400K, 0% used [0xe27f0000,0xe27f0000,0xe8bf0000)
  to   space 102400K, 0% used [0xdc3f0000,0xdc3f0000,0xe27f0000)
 ParOldGen       total 798720K, used 273778K [0x85ff0000, 0xb6bf0000,
0xb6bf0000)
  object space 798720K, 34% used [0x85ff0000,0x96b4ca40,0xb6bf0000)
 PSPermGen       total 98304K, used 75270K [0x7fff0000, 0x85ff0000,
0x85ff0000)
  object space 98304K, 76% used [0x7fff0000,0x849718a8,0x85ff0000)
}
Total time for which application threads were stopped: 17.9621428 seconds
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20120611/bf7e447b/attachment.html