java - JVM Garbage Collection Application Stopped Time Discrepancy -

i'm running large instance of tomcat following version of java:
java version "1.6.0_20"
openjdk runtime environment (icedtea6 1.9.7) (6b20-1.9.7-0ubuntu1~10.04.1
openjdk 64-bit server vm (build 19.0-b09, mixed mode)

and following parameter set:

-xms13152m   -xmx13152m   -xmn768m   -xx:+useconcmarksweepgc   -xx:cmsinitiatingoccupancyfraction=60   -xx:+cmsincrementalmode   -xx:+cmsincrementalpacing   -xx:cmsincrementaldutycyclemin=0   -xx:cmsincrementaldutycycle=10   -xx:+disableexplicitgc  

with gc debug statements enabled. every few hours see behavior in minor gc occurs , application stopped long time, gc not appear taking time:

{heap before gc invocations=392 (full 74):    par new generation   total 707840k, used 698252k [0x00000004bfa00000, 0x00000004efa00000, 0x00000004efa00000)     eden space 629248k,  99% used [0x00000004bfa00000, 0x00000004e607de48, 0x00000004e6080000)     space 78592k,  87% used [0x00000004ead40000, 0x00000004ef0a5370, 0x00000004efa00000)       space 78592k,   0% used [0x00000004e6080000, 0x00000004e6080000, 0x00000004ead40000)    concurrent mark-sweep generation total 12681216k, used 10877603k [0x00000004efa00000, 0x00000007f5a00000, 0x00000007f5a00000)    concurrent-mark-sweep perm gen total 50260k, used 30106k [0x00000007f5a00000, 0x00000007f8b15000, 0x0000000800000000)   13120.154: [gc 13120.154: [parnew desired survivor size 40239104 bytes, new threshold 1 (max 4) - age   1:   41912720 bytes,   41912720 total: 698252k->41387k(707840k), 0.1239080 secs] 11575856k->10987714k(13389056k) icms_dc=20 ,   0.1239930 secs] [times: user=0.00 sys=0.00, real=0.12 secs]    heap after gc invocations=393 (full 74):    par new generation   total 707840k, used 41387k [0x00000004bfa00000, 0x00000004efa00000, 0x00000004efa00000)     eden space 629248k,   0% used [0x00000004bfa00000, 0x00000004bfa00000, 0x00000004e6080000)     space 78592k,  52% used [0x00000004e6080000, 0x00000004e88eace0, 0x00000004ead40000)       space 78592k,   0% used [0x00000004ead40000, 0x00000004ead40000, 0x00000004efa00000)    concurrent mark-sweep generation total 12681216k, used 10946327k [0x00000004efa00000, 0x00000007f5a00000, 0x00000007f5a00000)    concurrent-mark-sweep perm gen total 50260k, used 30106k [0x00000007f5a00000, 0x00000007f8b15000, 0x0000000800000000)   }   total time application threads stopped: 32.1614890 seconds   

in case i'd expect gc stop application for, @ most, .12 seconds. have idea why there such huge discrepancy between application stopped time , gc time?

update i've included longer snippet gclog:

{heap before gc invocations=201 (full 18):  par new generation   total 707840k, used 639557k [0x00000004c4e00000, 0x00000004f4e00000, 0x00000004f4e00000)   eden space 629248k, 100% used [0x00000004c4e00000, 0x00000004eb480000, 0x00000004eb480000)   space 78592k,  13% used [0x00000004eb480000, 0x00000004ebe917e8, 0x00000004f0140000)     space 78592k,   0% used [0x00000004f0140000, 0x00000004f0140000, 0x00000004f4e00000)  concurrent mark-sweep generation total 12681216k, used 6634693k [0x00000004f4e00000, 0x00000007fae00000, 0x00000007fae00000)  concurrent-mark-sweep perm gen total 47232k, used 28977k [0x00000007fae00000, 0x00000007fdc20000, 0x0000000800000000) 2011-04-12t18:42:16.450+0000: 12770.352: [gc 12770.352: [parnew desired survivor size 40239104 bytes, new threshold 15 (max 15) - age   1:    3701392 bytes,    3701392 total - age   2:     517360 bytes,    4218752 total - age   3:    2113840 bytes,    6332592 total - age   4:    3489008 bytes,    9821600 total : 639557k->12278k(707840k), 0.0948620 secs] 7274251k->6646972k(13389056k) icms_dc=0 , 0.0949550 secs] [times: user=0.00 sys=0.00, real=0.10 secs]  heap after gc invocations=202 (full 18):  par new generation   total 707840k, used 12278k [0x00000004c4e00000, 0x00000004f4e00000, 0x00000004f4e00000)   eden space 629248k,   0% used [0x00000004c4e00000, 0x00000004c4e00000, 0x00000004eb480000)   space 78592k,  15% used [0x00000004f0140000, 0x00000004f0d3dbf0, 0x00000004f4e00000)     space 78592k,   0% used [0x00000004eb480000, 0x00000004eb480000, 0x00000004f0140000)  concurrent mark-sweep generation total 12681216k, used 6634693k [0x00000004f4e00000, 0x00000007fae00000, 0x00000007fae00000)  concurrent-mark-sweep perm gen total 47232k, used 28977k [0x00000007fae00000, 0x00000007fdc20000, 0x0000000800000000) } total time application threads stopped: 0.0952670 seconds application time: 5.0191420 seconds total time application threads stopped: 0.0001670 seconds application time: 2.2198130 seconds total time application threads stopped: 0.0004480 seconds application time: 5.5295710 seconds total time application threads stopped: 0.0001950 seconds application time: 0.0097140 seconds total time application threads stopped: 0.0000530 seconds application time: 7.1299730 seconds total time application threads stopped: 0.0001610 seconds application time: 12.0198160 seconds total time application threads stopped: 0.0001550 seconds application time: 1.5298610 seconds total time application threads stopped: 0.0001630 seconds application time: 0.0097650 seconds total time application threads stopped: 0.0000590 seconds application time: 0.1199330 seconds total time application threads stopped: 0.0000550 seconds application time: 10.0998880 seconds total time application threads stopped: 0.0003490 seconds application time: 1.0093980 seconds total time application threads stopped: 0.0003040 seconds application time: 0.6099830 seconds total time application threads stopped: 0.0001700 seconds application time: 0.0298490 seconds total time application threads stopped: 0.0000930 seconds application time: 0.2025080 seconds total time application threads stopped: 0.0023430 seconds application time: 0.0190510 seconds total time application threads stopped: 0.0003010 seconds application time: 0.1793310 seconds total time application threads stopped: 0.0002150 seconds application time: 0.0560830 seconds total time application threads stopped: 0.0010000 seconds application time: 1.7072960 seconds {heap before gc invocations=202 (full 18):  par new generation   total 707840k, used 641302k [0x00000004c4e00000, 0x00000004f4e00000, 0x00000004f4e00000)   eden space 629248k,  99% used [0x00000004c4e00000, 0x00000004eb447fd8, 0x00000004eb480000)   space 78592k,  15% used [0x00000004f0140000, 0x00000004f0d3dbf0, 0x00000004f4e00000)     space 78592k,   0% used [0x00000004eb480000, 0x00000004eb480000, 0x00000004f0140000)  concurrent mark-sweep generation total 12681216k, used 6634693k [0x00000004f4e00000, 0x00000007fae00000, 0x00000007fae00000)  concurrent-mark-sweep perm gen total 47232k, used 29039k [0x00000007fae00000, 0x00000007fdc20000, 0x0000000800000000) 2011-04-12t18:43:04.052+0000: 12817.954: [gc 12817.955: [parnew desired survivor size 40239104 bytes, new threshold 4 (max 15) - age   1:   36162128 bytes,   36162128 total - age   2:    2531664 bytes,   38693792 total - age   3:     420840 bytes,   39114632 total - age   4:    2052544 bytes,   41167176 total - age   5:    3484040 bytes,   44651216 total : 641302k->44375k(707840k), 0.2037750 secs] 7275996k->6679069k(13389056k) icms_dc=0 , 0.2039060 secs] [times: user=0.00 sys=0.00, real=0.21 secs]  heap after gc invocations=203 (full 18):  par new generation   total 707840k, used 44375k [0x00000004c4e00000, 0x00000004f4e00000, 0x00000004f4e00000)   eden space 629248k,   0% used [0x00000004c4e00000, 0x00000004c4e00000, 0x00000004eb480000)   space 78592k,  56% used [0x00000004eb480000, 0x00000004edfd5f88, 0x00000004f0140000)     space 78592k,   0% used [0x00000004f0140000, 0x00000004f0140000, 0x00000004f4e00000)  concurrent mark-sweep generation total 12681216k, used 6634693k [0x00000004f4e00000, 0x00000007fae00000, 0x00000007fae00000)  concurrent-mark-sweep perm gen total 47232k, used 29039k [0x00000007fae00000, 0x00000007fdc20000, 0x0000000800000000) } total time application threads stopped: 0.2043140 seconds application time: 0.0001040 seconds total time application threads stopped: 0.0000890 seconds application time: 4.0399400 seconds {heap before gc invocations=203 (full 18):  par new generation   total 707840k, used 673623k [0x00000004c4e00000, 0x00000004f4e00000, 0x00000004f4e00000)   eden space 629248k, 100% used [0x00000004c4e00000, 0x00000004eb480000, 0x00000004eb480000)   space 78592k,  56% used [0x00000004eb480000, 0x00000004edfd5f88, 0x00000004f0140000)     space 78592k,   0% used [0x00000004f0140000, 0x00000004f0140000, 0x00000004f4e00000)  concurrent mark-sweep generation total 12681216k, used 6634693k [0x00000004f4e00000, 0x00000007fae00000, 0x00000007fae00000)  concurrent-mark-sweep perm gen total 47232k, used 29040k [0x00000007fae00000, 0x00000007fdc20000, 0x0000000800000000) 2011-04-12t18:44:23.258+0000: 12897.160: [gc 12897.160: [parnew desired survivor size 40239104 bytes, new threshold 1 (max 15) - age   1:   46278472 bytes,   46278472 total - age   2:   23234248 bytes,   69512720 total - age   3:    2144024 bytes,   71656744 total - age   4:     391464 bytes,   72048208 total : 673623k->78592k(707840k), 0.1607580 secs] 7308317k->6752580k(13389056k) icms_dc=0 , 0.1608520 secs] [times: user=0.00 sys=0.00, real=0.16 secs]  heap after gc invocations=204 (full 18):  par new generation   total 707840k, used 78592k [0x00000004c4e00000, 0x00000004f4e00000, 0x00000004f4e00000)   eden space 629248k,   0% used [0x00000004c4e00000, 0x00000004c4e00000, 0x00000004eb480000)   space 78592k, 100% used [0x00000004f0140000, 0x00000004f4e00000, 0x00000004f4e00000)     space 78592k,   0% used [0x00000004eb480000, 0x00000004eb480000, 0x00000004f0140000)  concurrent mark-sweep generation total 12681216k, used 6673988k [0x00000004f4e00000, 0x00000007fae00000, 0x00000007fae00000)  concurrent-mark-sweep perm gen total 47232k, used 29040k [0x00000007fae00000, 0x00000007fdc20000, 0x0000000800000000) } total time application threads stopped: 75.1222720 seconds application time: 0.0660880 seconds total time application threads stopped: 0.0001500 seconds application time: 0.0001110 seconds total time application threads stopped: 0.0000620 seconds application time: 0.0000320 seconds total time application threads stopped: 0.0000620 seconds application time: 0.5790490 seconds total time application threads stopped: 0.0151370 seconds application time: 0.0241790 seconds total time application threads stopped: 0.0111420 seconds application time: 0.1488160 seconds total time application threads stopped: 0.0168360 seconds application time: 0.0237110 seconds total time application threads stopped: 0.0008580 seconds application time: 0.0594260 seconds total time application threads stopped: 0.0179450 seconds application time: 0.0331740 seconds total time application threads stopped: 0.0072850 seconds application time: 1.2617710 seconds {heap before gc invocations=204 (full 18):  par new generation   total 707840k, used 707840k [0x00000004c4e00000, 0x00000004f4e00000, 0x00000004f4e00000)   eden space 629248k, 100% used [0x00000004c4e00000, 0x00000004eb480000, 0x00000004eb480000)   space 78592k, 100% used [0x00000004f0140000, 0x00000004f4e00000, 0x00000004f4e00000)     space 78592k,   0% used [0x00000004eb480000, 0x00000004eb480000, 0x00000004f0140000)  concurrent mark-sweep generation total 12681216k, used 6673988k [0x00000004f4e00000, 0x00000007fae00000, 0x00000007fae00000)  concurrent-mark-sweep perm gen total 47232k, used 29089k [0x00000007fae00000, 0x00000007fdc20000, 0x0000000800000000) 2011-04-12t18:44:25.690+0000: 12899.592: [gc 12899.592: [parnew desired survivor size 40239104 bytes, new threshold 1 (max 15) - age   1:   42048296 bytes,   42048296 total : 707840k->58684k(707840k), 0.1654070 secs] 7381828k->6802196k(13389056k) icms_dc=0 , 0.1655450 secs] [times: user=0.00 sys=0.00, real=0.17 secs]  heap after gc invocations=205 (full 18):  par new generation   total 707840k, used 58684k [0x00000004c4e00000, 0x00000004f4e00000, 0x00000004f4e00000)   eden space 629248k,   0% used [0x00000004c4e00000, 0x00000004c4e00000, 0x00000004eb480000)   space 78592k,  74% used [0x00000004eb480000, 0x00000004eedcf320, 0x00000004f0140000)     space 78592k,   0% used [0x00000004f0140000, 0x00000004f0140000, 0x00000004f4e00000)  concurrent mark-sweep generation total 12681216k, used 6743511k [0x00000004f4e00000, 0x00000007fae00000, 0x00000007fae00000)  concurrent-mark-sweep perm gen total 47232k, used 29089k [0x00000007fae00000, 0x00000007fdc20000, 0x0000000800000000) } total time application threads stopped: 0.1709510 seconds application time: 1.0183040 seconds total time application threads stopped: 0.0009220 seconds application time: 0.0209220 seconds total time application threads stopped: 0.0009260 seconds application time: 0.0181760 seconds total time application threads stopped: 0.0002780 seconds application time: 0.0773630 seconds total time application threads stopped: 0.0019720 seconds application time: 0.0045340 seconds total time application threads stopped: 0.0001400 seconds application time: 0.0245930 seconds total time application threads stopped: 0.0004070 seconds application time: 0.4811530 seconds total time application threads stopped: 0.0043100 seconds application time: 0.0015090 seconds total time application threads stopped: 0.0052290 seconds application time: 0.0264570 seconds total time application threads stopped: 0.0072530 seconds application time: 0.0135600 seconds total time application threads stopped: 0.0121400 seconds application time: 0.0278510 seconds total time application threads stopped: 0.0078060 seconds application time: 0.0136080 seconds total time application threads stopped: 0.0121390 seconds application time: 0.0066360 seconds total time application threads stopped: 0.0004330 seconds application time: 0.0107480 seconds total time application threads stopped: 0.0001900 seconds application time: 0.0027230 seconds total time application threads stopped: 0.0132610 seconds application time: 0.0126600 seconds total time application threads stopped: 0.0003420 seconds application time: 0.5384840 seconds {heap before gc invocations=205 (full 18):  par new generation   total 707840k, used 687932k [0x00000004c4e00000, 0x00000004f4e00000, 0x00000004f4e00000)   eden space 629248k, 100% used [0x00000004c4e00000, 0x00000004eb480000, 0x00000004eb480000)   space 78592k,  74% used [0x00000004eb480000, 0x00000004eedcf320, 0x00000004f0140000)     space 78592k,   0% used [0x00000004f0140000, 0x00000004f0140000, 0x00000004f4e00000)  concurrent mark-sweep generation total 12681216k, used 6743511k [0x00000004f4e00000, 0x00000007fae00000, 0x00000007fae00000)  concurrent-mark-sweep perm gen total 47232k, used 29092k [0x00000007fae00000, 0x00000007fdc20000, 0x0000000800000000) 2011-04-12t18:44:28.223+0000: 12902.125: [gc 12902.125: [parnew desired survivor size 40239104 bytes, new threshold 15 (max 15) - age   1:    5906520 bytes,    5906520 total : 687932k->45478k(707840k), 0.2139570 secs] 7431444k->6860368k(13389056k) icms_dc=0 , 0.2142010 secs] [times: user=0.00 sys=0.00, real=0.21 secs]  heap after gc invocations=206 (full 18):  par new generation   total 707840k, used 45478k [0x00000004c4e00000, 0x00000004f4e00000, 0x00000004f4e00000)   eden space 629248k,   0% used [0x00000004c4e00000, 0x00000004c4e00000, 0x00000004eb480000)   space 78592k,  57% used [0x00000004f0140000, 0x00000004f2da9b30, 0x00000004f4e00000)     space 78592k,   0% used [0x00000004eb480000, 0x00000004eb480000, 0x00000004f0140000)  concurrent mark-sweep generation total 12681216k, used 6814889k [0x00000004f4e00000, 0x00000007fae00000, 0x00000007fae00000)  concurrent-mark-sweep perm gen total 47232k, used 29092k [0x00000007fae00000, 0x00000007fdc20000, 0x0000000800000000) } 

update

i switched application on multi-core machine alleviate pain cms collection , now, in steady state, don't see pauses. however, during updates search index, lot of large memory structures generated , application suffers long stw pauses again. i'm not sure how avoid objects should reside in tenured generation, increased size of survivor spaces (-xx:survivorratio=8) still observing long pauses. see below gc log:

 {heap before gc invocations=103 (full 48):  par new generation   total 921600k, used 912322k [0x000000050ce00000, 0x000000054b600000, 0x000000054b600000)   eden space 819200k,  99% used [0x000000050ce00000, 0x000000053e776380, 0x000000053ee00000)   space 102400k,  97% used [0x000000053ee00000, 0x0000000544f7a630, 0x0000000545200000)     space 102400k,   0% used [0x0000000545200000, 0x0000000545200000, 0x000000054b600000)  concurrent mark-sweep generation total 11264000k, used 6486203k [0x000000054b600000, 0x00000007fae00000, 0x00000007fae00000)  concurrent-mark-sweep perm gen total 48516k, used 29211k [0x00000007fae00000, 0x00000007 fdd61000, 0x0000000800000000) 2011-04-14t15:15:25.322+0000: 2358.684: [gc 2358.684: [parnew desired survivor size 52428800 bytes, new threshold 1 (max 15)- age   1:  102164088 bytes,  102164088 total : 912322k->99941k(921600k), 30.0146400 secs] 7398525k->6818473k(12185600k), 30.0147850 se cs] [times: user=0.00 sys=0.00, real=30.02 secs]  heap after gc invocations=104 (full 48): par new generation   total 921600k, used 99941k [0x000000050ce00000, 0x000000054b600000,  0x000000054b600000)   eden space 819200k,   0% used [0x000000050ce00000, 0x000000050ce00000, 0x000000053ee00000)   space 102400k,  97% used [0x0000000545200000, 0x000000054b399710, 0x000000054b6000 00)     space 102400k,   0% used [0x000000053ee00000, 0x000000053ee00000, 0x00000005452000 00) concurrent mark-sweep generation total 11264000k, used 6718531k [0x000000054b600000, 0x0 0000007fae00000, 0x00000007fae00000) concurrent-mark-sweep perm gen total 48516k, used 29211k [0x00000007fae00000, 0x00000007 fdd61000, 0x0000000800000000)} total time application threads stopped: 30.0152850 seconds application time: 0.9450500 seconds  

added comment longer gc log think survivor spaces small, note eden full survivor @ 56% before , eden not full after survivor @ 100%. means forced non concurrent tenured collection, reported young gc because not triggered cms, because has put garbage tenured. tenured collector can stuff tenured , hence full gc triggered. remedy making eden bigger and/or making survivor spaces bigger. can use survivorratio this, e.g -xx:survivorratio=8 means set each survivor space 1/8 of eden.

stopped time "time jvm spent @ safepoint", can use printsafepointstatistics determine going on during safepoint. this post has link list of operations cause vm reach safepoint which, if peruse it, show there many , varied ways sit there doing "nothing". don't rule out os clock shifts either times recorded via timeofday aware timestamp.

btw pre hotspot17 timestamps can inaccurate. bug described in bug id:6782663 fixed in hs17 part of 6u21 (as per the release notes). since you're on 6u20, (the 30s) may not real value.