Java CMS GC, потоки GC, берущие процессор, когда система простаивает

У нас есть веб-приложение на tomcat 7, JDK 7, Amazon Linux. Вот что мы имеем для конфигурации GC:

-XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled"

У нас не включена функция "PrintGCDetails".

Это то, что печатается в файле gc.log каждые несколько секунд (в течение 48 часов подряд, когда приложение в это время находится под нагрузкой 0 - абсолютно никакой активности, и даже в этом случае распечатывается следующее, а ЦП, занятый этими потоками, на 15%) (см. контекст ниже):

940568.925: [GC 7425641K(8277888K), 0.2201750 secs]
940572.415: [GC 7425641K(8277888K), 0.1782950 secs]
940574.101: [GC 7425641K(8277888K), 0.1736550 secs]
940577.545: [GC 7425647K(8277888K), 0.1779190 secs]

И мы видим, что следующие потоки GC занимают ЦП (всего около 15%), хотя:

  • в системе нет активности,
  • никакие другие потоки не активны, кроме этих, и это продолжается в течение 48 часов, и система в это время находилась под нагрузкой 0.
  • система была под нагрузкой 0 также в течение предыдущих 24 часов, а затем эти потоки стали активными
  • когда эти потоки были активны и занимали процессор, предыдущие строки были напечатаны в gc.log
  • Это продолжалось в течение 2 дней, и когда мы наконец загрузили, вызвав веб-приложение в этой JVM на 5 минут, а затем все прекратилось. Мы заметили, что эти потоки больше не загружают процессор (они берут <1 %) сейчас. Кажется, проблема решилась сама собой после того, как произойдет полный сбор данных. ПОЛНЫЙ ГХ произошел после того, как система была загружена.
  • Короче говоря, потоки GC продолжали занимать 15% ЦП, когда система находилась под нагрузкой 0 в течение 48 часов.

Вот эти темы:

"Gang worker#0 (Parallel GC Threads)" prio=10 tid=0x00007fad9402e000 nid=0x629d runnable
"Gang worker#1 (Parallel GC Threads)" prio=10 tid=0x00007fad94030000 nid=0x629e runnable
"Gang worker#2 (Parallel GC Threads)" prio=10 tid=0x00007fad94031800 nid=0x629f runnable
"Gang worker#3 (Parallel GC Threads)" prio=10 tid=0x00007fad94033800 nid=0x62a0 runnable
"Gang worker#4 (Parallel GC Threads)" prio=10 tid=0x00007fad94035800 nid=0x62a1 runnable
"Gang worker#5 (Parallel GC Threads)" prio=10 tid=0x00007fad94037000 nid=0x62a2 runnable
"Gang worker#6 (Parallel GC Threads)" prio=10 tid=0x00007fad94039000 nid=0x62a3 runnable
"Gang worker#7 (Parallel GC Threads)" prio=10 tid=0x00007fad9403b000 nid=0x62a4 runnable
"Gang worker#8 (Parallel GC Threads)" prio=10 tid=0x00007fad9403d000 nid=0x62a5 runnable
"Gang worker#9 (Parallel GC Threads)" prio=10 tid=0x00007fad9403e800 nid=0x62a6 runnable
"Gang worker#10 (Parallel GC Threads)" prio=10 tid=0x00007fad94040800 nid=0x62a7 runnable
"Gang worker#11 (Parallel GC Threads)" prio=10 tid=0x00007fad94042800 nid=0x62a8 runnable
"Gang worker#12 (Parallel GC Threads)" prio=10 tid=0x00007fad94044000 nid=0x62a9 runnable
"Concurrent Mark-Sweep GC Thread" prio=10 tid=0x00007fad9418b000 nid=0x62ae runnable
"Gang worker#0 (Parallel CMS Threads)" prio=10 tid=0x00007fad94183000 nid=0x62aa runnable
"Gang worker#1 (Parallel CMS Threads)" prio=10 tid=0x00007fad94185000 nid=0x62ab runnable
"Gang worker#2 (Parallel CMS Threads)" prio=10 tid=0x00007fad94187000 nid=0x62ac runnable
"Gang worker#3 (Parallel CMS Threads)" prio=10 tid=0x00007fad94188800 nid=0x62ad runnable

Вопрос 1: Почему журнал gc заполняется следующим, когда эти потоки занимают 15% ЦП?

940568.925: [GC 7425641K(8277888K), 0.2201750 secs]
940572.415: [GC 7425641K(8277888K), 0.1782950 secs]

Вопрос 2: Указывает ли вышеприведенный журнал сбой в CMS (отметка, развертка и т. Д.)?

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

Да, я постараюсь повторить проблему в другой среде с включенным printGCDetails и вернусь с информацией или решением - на случай, если кто-то видел это ранее, добавьте к беседе.

Редактировать 1: Это журнал, когда "PrintGCDetails" включен:

1376.326: [GC [1 CMS-initial-mark: 6481517K(7281088K)] 6536750K(8277888K), 0.0094620 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
1376.336: [CMS-concurrent-mark-start]
1377.992: [CMS-concurrent-mark: 1.656/1.656 secs] [Times: user=6.62 sys=0.00, real=1.66 secs] 
1377.992: [CMS-concurrent-preclean-start]
1378.005: [CMS-concurrent-preclean: 0.014/0.014 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 

1378.006: [CMS-concurrent-abortable-preclean-start]
CMS: abort preclean due to time 1413.110: [CMS-concurrent-abortable-preclean: 4.169/35.104 secs] [Times: user=4.23 sys=0.01, real=35.11 secs] 
1413.111: [GC[YG occupancy: 55233 K (996800 K)]1413.111: [Rescan (parallel) , 0.0154040 secs]1413.126: [weak refs processing, 0.0001380 secs]1413.126: [class unloading, 0.0013450 secs]1413.128: [scrub symbol table, 0.0023140 secs]1413.130: [scrub string table, 0.0004850 secs] [1 CMS-remark: 6481517K(7281088K)] 6536751K(8277888K), 0.0201870 secs] [Times: user=0.20 sys=0.00, real=0.02 secs] 
1413.131: [CMS-concurrent-sweep-start]
1414.151: [CMS-concurrent-sweep: 1.020/1.020 secs] [Times: user=1.02 sys=0.00, real=1.02 secs] 
1414.151: [CMS-concurrent-reset-start]
1414.177: [CMS-concurrent-reset: 0.026/0.026 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]

Также обратите внимание: "CMSMaxAbortablePrecleanTime" установлен на 35 секунд. Благодарю.

Источник

1 ответ

Решение

Должен быть адекватный буфер между занятой кучей и тем, что доступно. Увеличение размера (max) кучи, чтобы занятое место составляло 70% от общего числа, решило проблему. Это имеет особое значение, когда алгоритм CMS. Урок выучен.

Источник

UseConcMarkSweepGC используется для сбора мусора в старом поколении, а ваш вопрос 1 актуален для молодого поколения.

Почему заполнены журналы? Потому что именно так ваше приложение распределяет память. Вы выделяете много маленьких, молодых предметов. Коллектором по умолчанию в Young Generation является копирующий коллектор (однопоточный), который является полным сборщиком стоп-слов. Вы можете попробовать включить: -XX: + UseParNewGC для параллельного выполнения.

Что касается вашего вопроса 2, он не имеет ничего общего с ошибкой в ​​CMS, и причина кроется в пункте 1.

Вы можете сделать "Молодое поколение" больше с -XX:NewSize, чтобы задержать вызовы gc.

Источник
Другие вопросы по тегам