YGC (ParNew) в реальном времени намного больше времени пользователя + sys - PullRequest
Новая
       15

YGC (ParNew) в реальном времени намного больше времени пользователя + sys

0 голосов
/ 03 декабря 2011

У нас есть приложение на основе Web Java, работающее на JBoss с максимально допустимым размером кучи около 2,2 ГБ (Young Generation - 400 МБ, общая физическая память компьютера - 4 ГБ).В какой-то момент приложение перестает отвечать (клиентам) на несколько минут.После некоторого анализа мы обнаружили, что виновником является молодое поколение GC.Вот выдержка из подробного журнала GC: * ​​1001 * 

Heap before GC invocations=3844 (full 7):
 par new generation   total 614336K, used 614272K,  eden space 614272K, 100% used,  from space 64K,   0% used,  to   space 64K,   0% used , concurrent mark-sweep generation total 921600K, used 690936K, concurrent-mark-sweep perm gen total 262144K, used 65905K 2679114.965: [GC 2681684.725: [ParNew: 614272K->0K(614336K), 0.0132460 secs] 1305208K->692360K(1535936K), 0.0135020 secs] [Times: user=0.03 sys=0.03, real=2569.62 secs] 
Heap after GC invocations=3845 (full 7):
 par new generation   total 614336K, used 0K,  eden space 614272K,   0% used,  from space 64K,  to   space 64K,   0% used, concurrent mark-sweep generation total 921600K, used 692360K, concurrent-mark-sweep perm gen total 262144K, used 65905K
Total time for which application threads were stopped: 2569.7748610 seconds

Что я не понимаю, так это то, как возможно, что реальное время, проведенное на ParNew GC, составляет около 42 минут (2569 секунд), в то время как user + sysвремя составляет всего 0,06 секунды, а время паузы для второстепенного сбора составляет всего 0,0132460 секунд.

мы полагаем, что "перегрузка виртуальной памяти" или "высокая загрузка процессора" могут вызвать эту проблему, и мы тестируем два случая:

  1. мы запускаем несколько других программ, в которых используетсяв то время как цикл использует 100% ЦП, и журнал GC выглядит следующим образом: 6052.217: [GC 6052.217: [ParNew: 409288K-> 0K (409536K), 1.9456320 секунд] 480161K-> 72140K (1638336K), 1.9460370 секунд] [Times:user = 0.03 sys = 0.00, real = 1.95 sec]

  2. мы запускаем несколько других программ, которые занимают много памяти, и теперь журнал GC выглядит следующим образом: 11710.051: [GC 11710.058: [ParNew: 409472K-> 0K (409536K), 5,9080290 секунд] 489119K-> 81136K (1638336K), 5,9256280 секунд]

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

Но Куда уходит все остальное время?

1 Ответ

1 голос
/ 03 декабря 2011

Прежде чем остановить мировой сборщик мусора, все потоки должны достичь безопасной точки.Обычно это происходит довольно быстро, однако некоторые методы JNI могут работать долго без безопасной точки.Это одна из причин, по которой вы можете получить долгую задержку, прежде чем GC сможет действительно запуститься.

Если вы увидите это снова, то стоило бы получить трассировку стека уровня C (jstack, вероятно, не отвечаетдо тех пор, пока GC не будет выполнен)

...