Почему иногда происходят длительные задержки со сборкой мусора?

Question

Мне трудно разобраться с проблемой сборки мусора на Java и интерпретировать логи.

Мое приложение требует, чтобы ни один ГХ не занимал более 2 секунд, а в идеале менее 100 мс.

Исходя из некоторых предыдущих советов, я пробую следующие параметры командной строки:

 java -XX:MaxGCPauseMillis=100 -XX:NewRatio=9 -XX:+UseConcMarkSweepGC  -XX:+CMSIncrementalMode -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -server -Xmx9g -Xms9g 

Приложение имеет большое количество долгосрочных хранимых объектов, которые хранятся в ConcurrentLinkedHashMap. Я вижу случайные длинные паузы, в худшем случае до 10 секунд (это вторая последняя запись журналов GC ниже)!

Вот некоторые из выводов, которые я получаю:

16938.968: [GC 16938.968: [ParNew: 153343K->17022K(153344K), 7.8608580 secs] 6184328K->6122510K(9420160K) icms_dc=7 , 7.8614100 secs] [Times: user=0.63 sys=0.01, real=7.86 secs] 
16947.087: [GC 16947.087: [ParNew: 153342K->17022K(153344K), 7.2604030 secs] 6258830K->6198642K(9420160K) icms_dc=7 , 7.2609780 secs] [Times: user=0.44 sys=0.00, real=7.27 secs] 
16954.614: [GC 16954.614: [ParNew: 153342K->17024K(153344K), 8.4307620 secs] 6334962K->6274625K(9420160K) icms_dc=7 , 8.4313150 secs] [Times: user=0.62 sys=0.01, real=8.43 secs] 
16963.310: [GC 16963.310: [ParNew: 153344K->17023K(153344K), 6.2588760 secs] 6410945K->6350748K(9420160K) icms_dc=7 , 6.2594290 secs] [Times: user=0.48 sys=0.01, real=6.25 secs] 
16969.834: [GC 16969.834: [ParNew: 153343K->17022K(153344K), 6.0274280 secs] 6487068K->6425868K(9420160K) icms_dc=7 , 6.0279830 secs] [Times: user=0.50 sys=0.01, real=6.03 secs] 
16976.122: [GC 16976.123: [ParNew: 153342K->17022K(153344K), 11.7774620 secs] 6562188K->6503030K(9420160K) icms_dc=7 , 11.7780180 secs] [Times: user=0.43 sys=0.04, real=11.78 secs] 
16988.164: [GC 16988.164: [ParNew: 153342K->17024K(153344K), 10.9477920 secs] 6639350K->6579928K(9420160K) icms_dc=7 , 10.9483440 secs] [Times: user=0.37 sys=0.02, real=10.95 secs] 
16999.371: [GC 16999.372: [ParNew: 153344K->17023K(153344K), 9.8828360 secs] 6716248K->6655886K(9420160K) icms_dc=7 , 9.8833940 secs] [Times: user=0.42 sys=0.01, real=9.88 secs] 
17009.509: [GC 17009.509: [ParNew: 153343K->17023K(153344K), 5.0699960 secs] 6792206K->6727987K(9420160K) icms_dc=7 , 5.0705660 secs] [Times: user=0.55 sys=0.01, real=5.07 secs] 
17014.838: [GC 17014.838: [ParNew: 153343K->17023K(153344K), 6.6411750 secs] 6864307K->6790974K(9420160K) icms_dc=7 , 6.6417400 secs] [Times: user=0.37 sys=0.01, real=6.63 secs] 
17021.735: [GC 17021.735: [ParNew: 153343K->17024K(153344K), 8.0545970 secs] 6927294K->6856409K(9420160K) icms_dc=7 , 8.0551790 secs] [Times: user=0.34 sys=0.03, real=8.05 secs] 
17030.052: [GC 17030.053: [ParNew: 153344K->17023K(153344K), 7.9756730 secs] 6992729K->6922569K(9420160K) icms_dc=7 , 7.9762530 secs] [Times: user=0.34 sys=0.01, real=7.98 secs] 
17038.398: [GC 17038.398: [ParNew: 153343K->17022K(153344K), 12.9613300 secs] 7058889K->6990725K(9420160K) icms_dc=7 , 12.9618850 secs] [Times: user=0.39 sys=0.01, real=12.96 secs] 
17051.630: [GC 17051.630: [ParNew: 153342K->17022K(153344K), 6.8942910 secs] 7127045K->7059607K(9420160K) icms_dc=7 , 6.8948380 secs] [Times: user=0.56 sys=0.02, real=6.89 secs] 
17058.798: [GC 17058.798: [ParNew: 153342K->17024K(153344K), 10.0262190 secs] 7195927K->7126351K(9420160K) icms_dc=7 , 10.0267860 secs] [Times: user=0.37 sys=0.01, real=10.02 secs] 
17069.096: [GC 17069.096: [ParNew: 153344K->17023K(153344K), 10.0419500 secs] 7262671K->7195002K(9420160K) icms_dc=7 , 10.0425020 secs] [Times: user=0.40 sys=0.02, real=10.04 secs] 
17079.410: [GC 17079.410: [ParNew: 153343K->17022K(153344K), 13.5389040 secs] 7331322K->7264275K(9420160K) icms_dc=7 , 13.5394610 secs] [Times: user=0.30 sys=0.01, real=13.54 secs] 
17093.223: [GC 17093.224: [ParNew: 153342K->17023K(153344K), 10.5909450 secs] 7400595K->7330446K(9420160K) icms_dc=7 , 10.5915060 secs] [Times: user=0.33 sys=0.00, real=10.58 secs] 
17104.083: [GC 17104.084: [ParNew: 153343K->17024K(153344K), 5.8420210 secs] 7466766K->7392173K(9420160K) icms_dc=7 , 5.8425920 secs] [Times: user=0.57 sys=0.00, real=5.84 secs] 

Я часами пролистывал различные веб-страницы, описывающие настройку Java GC, но ни одна из них не дала мне возможности интерпретировать журналы, приведенные выше, и придумать курс действий. Будем весьма благодарны за любые конкретные советы, основанные на предоставленных мною журналах.

Обновление: По вопросу ниже:

Машина имеет 16 ГБ оперативной памяти, вот информация сверху: Память: всего 15483904 КБ, использовано 15280084 КБ, свободно 203820 КБ, буферов 155684 КБ Обмен: всего 2031608 тыс., Использовано 1347240 тыс., Свободно 684368 тыс., Кэшировано 3304044 тыс.

Это другой прогон, но вот текущий верхний вывод для процесса:

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
  1016 sanity   17   0 10.2g 6.5g 9464 S    1 44.2  10:24.32 java                      

Обновление 2: Некоторые более подробные записи, похоже, что это вызвало задержку 400 мс:

{Heap before GC invocations=1331 (full 1):
 par new generation   total 153344K, used 153343K [0x00002aaaae200000, 0x00002aaab8860000, 0x00002aaab8860000)
  eden space 136320K, 100% used [0x00002aaaae200000, 0x00002aaab6720000, 0x00002aaab6720000)
  from space 17024K,  99% used [0x00002aaab77c0000, 0x00002aaab885fff0, 0x00002aaab8860000)
  to   space 17024K,   0% used [0x00002aaab6720000, 0x00002aaab6720000, 0x00002aaab77c0000)
 concurrent mark-sweep generation total 7169664K, used 4258496K [0x00002aaab8860000, 0x00002aac6e200000, 0x00002aac6e200000)
 concurrent-mark-sweep perm gen total 21248K, used 13269K [0x00002aac6e200000, 0x00002aac6f6c0000, 0x00002aac73600000)
484.738: [GC 484.738: [ParNew: 153343K->17022K(153344K), 0.3950480 secs] 4411840K->4341689K(7323008K), 0.3954820 secs] [Times: user=0.49 sys=0.07, real=0.40 secs] 
Heap after GC invocations=1332 (full 1):
 par new generation   total 153344K, used 17022K [0x00002aaaae200000, 0x00002aaab8860000, 0x00002aaab8860000)
  eden space 136320K,   0% used [0x00002aaaae200000, 0x00002aaaae200000, 0x00002aaab6720000)
  from space 17024K,  99% used [0x00002aaab6720000, 0x00002aaab77bfb68, 0x00002aaab77c0000)
  to   space 17024K,   0% used [0x00002aaab77c0000, 0x00002aaab77c0000, 0x00002aaab8860000)
 concurrent mark-sweep generation total 7169664K, used 4324666K [0x00002aaab8860000, 0x00002aac6e200000, 0x00002aac6e200000)
 concurrent-mark-sweep perm gen total 21248K, used 13269K [0x00002aac6e200000, 0x00002aac6f6c0000, 0x00002aac73600000)
}

Answer 1

Оказалось, что проблема заключалась в том, что куча была выгружена на диск, и задержка была из-за того, что Java-сборщик должен был ждать, пока он не будет заменен.

Решено (в основном) путем установки параметра Linux "swappiness" на 0.

Answer 2

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

Просто дикая догадка: разве это не поменяется? Сколько памяти у машины? Сколько из этого получает процесс Java (размер резидентного набора)?

Изменить: почему он ждет:

Посмотрите на это (из вашего стенограммы)

[Times: user=0.39 sys=0.01, real=12.96 secs]

Это означает, что (я думаю, от начала до конца GC) прошло 12 (почти 13) секунд. Из этих 13 секунд .39 было потрачено на работу в режиме пользователя, 0,01 - на работу в режиме ядра. Если метод сбора времени не является полностью ошибочным (т. Е. Числа действительно представляют время выполнения процесса / потока GC), это означает ожидание не менее 12 секунд.

Answer 3

В общем, сложно настроить GC правильно, когда вам нужна такая большая куча.

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

Инициализирован ли ваш ConcurrentLinkedHashMap со всеми постоянными в памяти объектами одновременно? Или оно медленно увеличивается по мере того, как приложение продолжает работать? Если это последнее, может быть трудно сократить время зависания ГХ, поскольку есть объекты, которые всегда выживают. Если это первое, вам нужно измерить ваше постоянное поколение с размером ваших постоянных объектов + 20% или около того, и убедиться, что ваш молодой ген достаточно велик, чтобы не отставать от переходных объектов, созданных в ходе ваше заявление.

Answer 4

Я думаю, что у вас есть UseConcMarkSweepGC и ошибка NewRatio . Так как ваше новое пространство совсем не близко к десятой части -Jmx=9G. Ошибка включает обходной путь (NewSize в абсолютном размере).

Еще один флаг, который может быть очень важен для вас, - CMSInitiatingOccupancyFraction. Это установлено в 92% в java6 и было 68% в java5. Если старое пространство становится больше, пул потоков CMS начнет выполнять свою работу. Если у вас есть процессор, который вы можете потратить, то нет опасности иметь живое множество, которое выше начальной доли.

Было бы неплохо, если бы вы включили статистику GC после того, как исправили проблему с подкачкой памяти.

Answer 5

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

Answer 6

для меня проблемой было полное выживание пробелов. Поскольку CMS не является компактной, мусор был переведен непосредственно на старый ген. это может быть очень дорого с такой большой кучей. Необходимо максимально увеличить количество мест Survivor и MaxTenuringThreshold, чтобы избежать максимально возможного повышения.

С уважением, Алекс

Answer 7

9 ГБ JVM! Никогда раньше такого не видел! Я думаю, что ваши 10 сек. паузы вполне нормальные. посмотрите это (может быть, вы уже читали это ...)

Answer 8

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

Answer 9

Я думаю, что ваше внимание может быть немного перенаправлено.

Потратьте немного времени в профилировщике, чтобы найти ваши самые горячие точки выделения. Если в вашем коде есть только несколько мест, где происходит большинство ваших выделений, попробуйте использовать пул объектов, а не всегда создавать новые объекты.

Классы коллекций и StringBuilders - отличные кандидаты на объединение. Когда вы возвращаете их в пул, вызывайте методы collection.clear () или stringbuilder.setLength (0), чтобы они были готовы к потреблению, когда следующий вызывающий абонент хочет извлечь их из пула.

Лучший способ настроить GC - создавать меньше объектов. Существует множество стратегий устранения выделений, и объединение в пул - это только одна из них (хотя одна из моих любимых).

ОБНОВЛЕНИЕ: Прошло пять лет с тех пор, как я написал этот ответ, и мое мнение о пуле в основном изменилось. Когда я писал этот ответ в 2009 году, я часто использовал пул объектов (даже таких простых объектов, как StringBuilder), чтобы ускорить сжатые внутренние циклы с большим количеством выделений. В наши дни сложнее найти случаи, когда объединение не ухудшает ситуацию. Я почти никогда не использую пулы для чего-либо кроме потоков или соединений. Тем не менее, это хороший инструмент в вашем распоряжении, даже если вы не используете его часто.

Answer 10

Это может быть очень трудно сказать, не видя, а в некоторых случаях профилируя код.

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