Приложение сбора мусора в JVM остановилось - PullRequest
Новая
       1

Приложение сбора мусора в JVM остановилось

3 голосов
/ 11 апреля 2011

Я использую большой экземпляр 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?

UPDATE Я включил более длинный фрагмент из 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: * ​​1019 * 


{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 ]

3 голосов
/ 12 апреля 2011

добавлен комментарий к длинному журналу GC Я думаю, что ваши места выживших слишком малы, обратите внимание, что eden заполнен выжившим на 56% раньше, а eden не заполнен после, но выживший на 100%. Это означает, что он принудительно создается в совершенно не параллельную коллекцию с правами владения, которая, как сообщается, является молодой командой gc, потому что она не была вызвана CMS, потому что ей некуда добавить лишний мусор, но заслужили. Только штатный коллекционер может делать вещи для арендованного, и, следовательно, запускается полный сборщик мусора. Средство защиты делает райд больше и / или пространство для выживших больше. Для этого вы можете использовать SurvivorRatio, например, -XX:SurvivorRatio=8 означает, что для каждого оставшегося в живых места должно быть 1/8 от Эдема.

Остановленное время - это действительно «время, проведенное JVM в безопасной точке», вы можете использовать PrintSafepointStatistics, чтобы определить, что происходило во время безопасной точки. Этот пост содержит ссылку на список операций, которые заставляют виртуальную машину достигать безопасной точки, которая, если вы просматриваете ее, покажет, что существует множество различных способов, которыми она могла бы сидеть и ничего не делать. Не исключайте сдвиги часов ОС, так как время записывается с помощью метки времени с указанием времени дня.

btw pre hotspot17, эти временные метки могут быть неточными. Ошибка описана в Идентификатор ошибки: 6782663 , который был исправлен в hs17, который был частью 6u21 (согласно примечаниям к выпуску ). Поскольку вы находитесь на 6u20, это (30-е годы) может даже не быть реальной стоимостью.

1 голос
/ 12 апреля 2011

В некоторых случаях одновременный сборщик возвращается к полной сборке мусора, которая останавливает все до завершения. Если я правильно помню, маленький eden может вызвать его, если приложение создает много объектов, которые нужно собрать, и они не могут поддерживать. Возможно, вы захотите попробовать указать больший eden (или использовать соотношение, чтобы оно правильно масштабировалось с памятью). Вы можете попробовать добавить эти параметры конфигурации, чтобы получить больше деталей GC, если у вас их еще нет: 

-Xloggc:gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps

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

-Xms24g -Xmx24g -XX:MaxPermSize=256m -XX:NewRatio=4 -XX:SurvivorRatio=8    
-XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+DisableExplicitGC  
-XX:+UseCMSInitiatingOccupancyOnly -XX:+CMSClassUnloadingEnabled  
-XX:+CMSScavengeBeforeRemark -XX:CMSInitiatingOccupancyFraction=68

Поскольку мы используем 32 ГБ, мы также используем -XX:+UseCompressedOops, чтобы уменьшить накладные расходы при 64-битной адресации. Кроме того, мы используем -XX:+UseLargePages для повышения производительности, однако сначала необходимо включить поддержку больших страниц для вашей ОС.

...