Help, full gc takes forever

[Chi Ho Kwok]

Hi there,

It's the swap. When the real time is much higher than user+sys, the CPU is
idle while waiting for data. You must reserve some space for the OS,
running a 4GB heap on 4GB physical RAM does not work that well as you can
see. Try 3GB or 3.5GB, it's better to be safe than sorry with swap.

Regards,
Chi Ho Kwok

On Mon, Jun 11, 2012 at 4:10 PM, Office Consotec <hotspotgc42 at googlemail.com
> wrote:

>
> 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
>
>
>
>
> _______________________________________________
> hotspot-gc-use mailing list
> hotspot-gc-use at openjdk.java.net
> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20120611/eb5f0c31/attachment.html