операторы журнала в Q показывают одно событие GC, поэтому, если OP не удалил релевантную информацию и просто напечатал одну строку, то принудительный полный GC не может продолжаться.

ользую большой экземпляр Tomcat со следующей версией Java:
Java-версия "1.6.0_20"
Среда выполнения OpenJDK (IcedTea6 1.9.7) (6b20-1.9.7-0ubuntu1 ~ 10.04.1
64-битная серверная виртуальная машина OpenJDK (сборка 19.0-b09, смешанный режим)

и со следующим набором параметров:

-Xms13152m  
-Xmx13152m  
-Xmn768m  
-XX:+UseConcMarkSweepGC  
-XX:CMSInitiatingOccupancyFraction=60  
-XX:+CMSIncrementalMode  
-XX:+CMSIncrementalPacing  
-XX:CMSIncrementalDutyCycleMin=0  
-XX:CMSIncrementalDutyCycle=10  
-XX:+DisableExplicitGC 

с включенными инструкциями отладки GC. Каждые несколько часов я вижу поведение, при котором происходит незначительный сборщик мусора, и приложение останавливается на долгое время, но сам сборщик мусора, похоже, не занимает так много времени:

{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)  
  from space 78592K,  87% used [0x00000004ead40000, 0x00000004ef0a5370, 0x00000004efa00000)  
  to   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)  
  from space 78592K,  52% used [0x00000004e6080000, 0x00000004e88eace0, 0x00000004ead40000)  
  to   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 for which application threads were stopped: 32.1614890 seconds  

В этом случае я ожидаю, что сборщик мусора остановит приложение максимум на 0,12 секунды. Кто-нибудь знает, почему существует такое огромное расхождение между временем остановки приложения и временем GC?

ОБНОВЛЕНИЕ Я включил более длинный фрагмент из 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)
  from space 78592K,  13% used [0x00000004eb480000, 0x00000004ebe917e8, 0x00000004f0140000)
  to   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)
  from space 78592K,  15% used [0x00000004f0140000, 0x00000004f0d3dbf0, 0x00000004f4e00000)
  to   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 for which application threads were stopped: 0.0952670 seconds
Application time: 5.0191420 seconds
Total time for which application threads were stopped: 0.0001670 seconds
Application time: 2.2198130 seconds
Total time for which application threads were stopped: 0.0004480 seconds
Application time: 5.5295710 seconds
Total time for which application threads were stopped: 0.0001950 seconds
Application time: 0.0097140 seconds
Total time for which application threads were stopped: 0.0000530 seconds
Application time: 7.1299730 seconds
Total time for which application threads were stopped: 0.0001610 seconds
Application time: 12.0198160 seconds
Total time for which application threads were stopped: 0.0001550 seconds
Application time: 1.5298610 seconds
Total time for which application threads were stopped: 0.0001630 seconds
Application time: 0.0097650 seconds
Total time for which application threads were stopped: 0.0000590 seconds
Application time: 0.1199330 seconds
Total time for which application threads were stopped: 0.0000550 seconds
Application time: 10.0998880 seconds
Total time for which application threads were stopped: 0.0003490 seconds
Application time: 1.0093980 seconds
Total time for which application threads were stopped: 0.0003040 seconds
Application time: 0.6099830 seconds
Total time for which application threads were stopped: 0.0001700 seconds
Application time: 0.0298490 seconds
Total time for which application threads were stopped: 0.0000930 seconds
Application time: 0.2025080 seconds
Total time for which application threads were stopped: 0.0023430 seconds
Application time: 0.0190510 seconds
Total time for which application threads were stopped: 0.0003010 seconds
Application time: 0.1793310 seconds
Total time for which application threads were stopped: 0.0002150 seconds
Application time: 0.0560830 seconds
Total time for which application threads were 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)
  from space 78592K,  15% used [0x00000004f0140000, 0x00000004f0d3dbf0, 0x00000004f4e00000)
  to   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)
  from space 78592K,  56% used [0x00000004eb480000, 0x00000004edfd5f88, 0x00000004f0140000)
  to   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 for which application threads were stopped: 0.2043140 seconds
Application time: 0.0001040 seconds
Total time for which application threads were 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)
  from space 78592K,  56% used [0x00000004eb480000, 0x00000004edfd5f88, 0x00000004f0140000)
  to   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)
  from space 78592K, 100% used [0x00000004f0140000, 0x00000004f4e00000, 0x00000004f4e00000)
  to   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 for which application threads were stopped: 75.1222720 seconds
Application time: 0.0660880 seconds
Total time for which application threads were stopped: 0.0001500 seconds
Application time: 0.0001110 seconds
Total time for which application threads were stopped: 0.0000620 seconds
Application time: 0.0000320 seconds
Total time for which application threads were stopped: 0.0000620 seconds
Application time: 0.5790490 seconds
Total time for which application threads were stopped: 0.0151370 seconds
Application time: 0.0241790 seconds
Total time for which application threads were stopped: 0.0111420 seconds
Application time: 0.1488160 seconds
Total time for which application threads were stopped: 0.0168360 seconds
Application time: 0.0237110 seconds
Total time for which application threads were stopped: 0.0008580 seconds
Application time: 0.0594260 seconds
Total time for which application threads were stopped: 0.0179450 seconds
Application time: 0.0331740 seconds
Total time for which application threads were 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)
  from space 78592K, 100% used [0x00000004f0140000, 0x00000004f4e00000, 0x00000004f4e00000)
  to   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)
  from space 78592K,  74% used [0x00000004eb480000, 0x00000004eedcf320, 0x00000004f0140000)
  to   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 for which application threads were stopped: 0.1709510 seconds
Application time: 1.0183040 seconds
Total time for which application threads were stopped: 0.0009220 seconds
Application time: 0.0209220 seconds
Total time for which application threads were stopped: 0.0009260 seconds
Application time: 0.0181760 seconds
Total time for which application threads were stopped: 0.0002780 seconds
Application time: 0.0773630 seconds
Total time for which application threads were stopped: 0.0019720 seconds
Application time: 0.0045340 seconds
Total time for which application threads were stopped: 0.0001400 seconds
Application time: 0.0245930 seconds
Total time for which application threads were stopped: 0.0004070 seconds
Application time: 0.4811530 seconds
Total time for which application threads were stopped: 0.0043100 seconds
Application time: 0.0015090 seconds
Total time for which application threads were stopped: 0.0052290 seconds
Application time: 0.0264570 seconds
Total time for which application threads were stopped: 0.0072530 seconds
Application time: 0.0135600 seconds
Total time for which application threads were stopped: 0.0121400 seconds
Application time: 0.0278510 seconds
Total time for which application threads were stopped: 0.0078060 seconds
Application time: 0.0136080 seconds
Total time for which application threads were stopped: 0.0121390 seconds
Application time: 0.0066360 seconds
Total time for which application threads were stopped: 0.0004330 seconds
Application time: 0.0107480 seconds
Total time for which application threads were stopped: 0.0001900 seconds
Application time: 0.0027230 seconds
Total time for which application threads were stopped: 0.0132610 seconds
Application time: 0.0126600 seconds
Total time for which application threads were 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)
  from space 78592K,  74% used [0x00000004eb480000, 0x00000004eedcf320, 0x00000004f0140000)
  to   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)
  from space 78592K,  57% used [0x00000004f0140000, 0x00000004f2da9b30, 0x00000004f4e00000)
  to   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)
}

ОБНОВИТЬ

Я переключил свое приложение на многоядерный компьютер, чтобы облегчить боль в коллекции CMS, и теперь, в устойчивом состоянии, я не вижу никаких пауз. Однако во время обновления моего поискового индекса быстро генерируется много больших структур памяти, и приложение снова страдает от длительных пауз STW. Я не уверен, как этого избежать, поскольку эти объекты, вероятно, должны находиться в заемном поколении, я увеличил размер своих мест для выживших (-XX: SurvivorRatio = 8), но все еще наблюдаю длинные паузы. Смотрите журнал GC ниже:


{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)
  from space 102400K,  97% used [0x000000053ee00000, 0x0000000544f7a630, 0x0000000545200000)
  to   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)
  from space 102400K,  97% used [0x0000000545200000, 0x000000054b399710, 0x000000054b6000
00)
  to   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 for which application threads were stopped: 30.0152850 seconds
Application time: 0.9450500 seconds

Ответы на вопрос(2)

Ваш ответ на вопрос