Подтвердить что ты не робот

Почему параллельная метка и развертка (CMS) не очищают тот же объем памяти, что и Full GC?

У меня странная проблема с одной из моих производственных машин. В нем размещено приложение Java, которое делает CMS (параллельная метка и развертка), но она очищает только небольшую часть старого поколения. Я подозревал утечку памяти и пытался сбросить кучу. Но полный GC, предшествующий куче кучи, очищает почти все старые поколения. Что происходит? Я никогда не видел такого поведения сборки мусора Java. Обычно CMS и Full GC должны собирать примерно столько же мусора, теперь CMS хранит около 10 ГБ.

  • Java 1.7.0_75
  • Linux Cent OS 7

GC logs:

**2016-01-04T07:37:40.196+0000: 431200.698: [GC [1 CMS-initial-mark: 21633423K(27336704K)] 22826703K(30101504K), 4.3910840 secs] [Times: user=4.40 sys=0.01, real=4.39 secs] 
2016-01-04T07:37:44.588+0000: 431205.090: [CMS-concurrent-mark-start]
2016-01-04T07:38:08.718+0000: 431229.220: [CMS-concurrent-mark: 18.213/24.131 secs] [Times: user=126.00 sys=2.22, real=24.13 secs] 
2016-01-04T07:38:08.718+0000: 431229.220: [CMS-concurrent-preclean-start]
2016-01-04T07:38:08.843+0000: 431229.345: [CMS-concurrent-preclean: 0.118/0.125 secs] [Times: user=0.29 sys=0.00, real=0.12 secs] 
2016-01-04T07:38:08.843+0000: 431229.345: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2016-01-04T07:38:13.906+0000: 431234.408: [CMS-concurrent-abortable-preclean: 4.975/5.063 secs] [Times: user=10.18 sys=0.03, real=5.06 secs] 
2016-01-04T07:38:14.001+0000: 431234.503: [GC[YG occupancy: 1312993 K (2764800 K)]2016-01-04T07:38:14.001+0000: 431234.503: [Rescan (parallel) , 4.6981760 secs]2016-01-04T07:38:18.699+0000: 431239.202: [weak refs processing, 0.0002970 secs]2016-01-04T07:38:18.700+0000: 431239.202: [scrub string table, 0.0006900 secs] [1 CMS-remark: 21633423K(27336704K)] 22946417K(30101504K), 4.6993310 secs] [Times: user=105.40 sys=0.36, real=4.70 secs] 
2016-01-04T07:38:18.701+0000: 431239.203: [CMS-concurrent-sweep-start]
2016-01-04T07:38:27.967+0000: 431248.469: [CMS-concurrent-sweep: 9.160/9.267 secs] [Times: user=17.91 sys=0.10, real=9.26 secs] 
2016-01-04T07:38:27.968+0000: 431248.470: [CMS-concurrent-reset-start]
2016-01-04T07:38:28.028+0000: 431248.531: [CMS-concurrent-reset: 0.061/0.061 secs] [Times: user=0.14 sys=0.00, real=0.06 secs]** 
2016-01-04T07:38:30.801+0000: 431251.303: [GC [1 CMS-initial-mark: 21633105K(27336704K)] 23039228K(30101504K), 5.6079370 secs] [Times: user=5.60 sys=0.01, real=5.61 secs] 
2016-01-04T07:38:36.409+0000: 431256.911: [CMS-concurrent-mark-start]
2016-01-04T07:38:54.673+0000: 431275.175: [CMS-concurrent-mark: 17.807/18.264 secs] [Times: user=119.97 sys=1.66, real=18.26 secs] 
2016-01-04T07:38:54.673+0000: 431275.175: [CMS-concurrent-preclean-start]
2016-01-04T07:38:54.799+0000: 431275.301: [CMS-concurrent-preclean: 0.119/0.126 secs] [Times: user=0.25 sys=0.00, real=0.13 secs] 
2016-01-04T07:38:54.799+0000: 431275.301: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2016-01-04T07:39:01.382+0000: 431281.884: [CMS-concurrent-abortable-preclean: 6.478/6.583 secs] [Times: user=12.23 sys=0.06, real=6.58 secs] 
2016-01-04T07:39:01.487+0000: 431281.989: [GC[YG occupancy: 1596183 K (2764800 K)]2016-01-04T07:39:01.487+0000: 431281.989: [Rescan (parallel) , 3.5737630 secs]2016-01-04T07:39:05.061+0000: 431285.563: [weak refs processing, 0.0002690 secs]2016-01-04T07:39:05.061+0000: 431285.563: [scrub string table, 0.0005740 secs] [1 CMS-remark: 21633105K(27336704K)] 23229288K(30101504K), 3.5747910 secs] [Times: user=80.26 sys=0.27, real=3.58 secs] 
2016-01-04T07:39:05.062+0000: 431285.564: [CMS-concurrent-sweep-start]
2016-01-04T07:39:21.895+0000: 431302.397: [CMS-concurrent-sweep: 9.449/16.834 secs] [Times: user=27.52 sys=0.16, real=16.83 secs] 
2016-01-04T07:39:21.895+0000: 431302.397: [CMS-concurrent-reset-start]
2016-01-04T07:39:21.995+0000: 431302.497: [CMS-concurrent-reset: 0.099/0.099 secs] [Times: user=0.23 sys=0.01, real=0.10 secs] 
2016-01-04T07:39:24.104+0000: 431304.606: [GC [1 CMS-initial-mark: **21631742K(27336704K)**] 23455261K(30101504K), 5.6592940 secs] [Times: user=5.67 sys=0.00, real=5.66 secs] 
2016-01-04T07:39:29.764+0000: 431310.266: [CMS-concurrent-mark-start]
2016-01-04T07:39:56.859+0000: 431337.361: [CMS-concurrent-mark: 19.813/27.096 secs] [Times: user=140.17 sys=2.62, real=27.10 secs] 
2016-01-04T07:39:56.859+0000: 431337.361: [CMS-concurrent-preclean-start]
2016-01-04T07:39:57.102+0000: 431337.604: [CMS-concurrent-preclean: 0.152/0.242 secs] [Times: user=0.35 sys=0.00, real=0.24 secs] 
2016-01-04T07:39:57.102+0000: 431337.604: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2016-01-04T07:40:03.016+0000: 431343.518: [CMS-concurrent-abortable-preclean: 5.376/5.914 secs] [Times: user=11.65 sys=0.05, real=5.91 secs] 
2016-01-04T07:40:03.016+0000: 431343.518: [GC[YG occupancy: 2045175 K (2764800 K)]2016-01-04T07:40:03.016+0000: 431343.518: [Rescan (parallel) , 3.4843400 secs]2016-01-04T07:40:06.501+0000: 431347.003: [weak refs processing, 0.0002510 secs]2016-01-04T07:40:06.501+0000: 431347.003: [scrub string table, 0.0006220 secs] [1 CMS-remark: **21631742K(27336704K)**] 23676918K(30101504K), 3.4853760 secs] [Times: user=78.31 sys=0.27, real=3.49 secs] 
2016-01-04T07:40:06.502+0000: 431347.004: [CMS-concurrent-sweep-start]
{Heap before GC invocations=1832 (full 5077):
 par new generation   total 2764800K, used 2166647K [0x00000000bae00000, 0x0000000176600000, 0x0000000176600000)
  eden space 2457600K,  77% used [0x00000000bae00000, 0x000000012e6a4c90, 0x0000000150e00000)
  from space 307200K,  89% used [0x0000000150e00000, 0x0000000161939318, 0x0000000163a00000)
  to   space 307200K,   0% used [0x0000000163a00000, 0x0000000163a00000, 0x0000000176600000)
 concurrent mark-sweep generation total 27336704K, used 21631644K [0x0000000176600000, 0x00000007fae00000, 0x00000007fae00000)
 concurrent-mark-sweep perm gen total 49956K, used 30116K [0x00000007fae00000, 0x00000007fdec9000, 0x0000000800000000)
**2016-01-04T07:40:12.775+0000: 431353.277: [Full GC2016-01-04T07:40:12.775+0000: 431353.277: [CMS2016-01-04T07:40:17.924+0000: 431358.426: [CMS-concurrent-sweep: 9.211/11.422 secs] [Times: user=16.59 sys=0.15, real=11.42 secs] 
 (concurrent mode interrupted): 21631644K->4907878K(27336704K), 39.2467600 secs] 23798292K->4907878K(30101504K), [CMS Perm : 30116K->28023K(49956K)], 39.2468730 secs] [Times: user=39.24 sys=0.05, real=39.25 secs]**

То же приложение работает нормально на другом компьютере, используя Cent OS 5, java 7.

java -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=1581
-Dcom.sun.management.jmxremote.authenticate=false
-Dcom.sun.management.jmxremote.ssl=false -verbose:gc -XX:+PrintGCDetails
-XX:+UseCompressedOops -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC
-XX:+PrintTenuringDistribution -XX:+UseConcMarkSweepGC
-Xloggc:/usr/local/app/logs/current-gc.log -Xms29g -Xmx29g -XX:NewSize=3000m
-XX:SurvivorRatio=8 -XX:CMSInitiatingOccupancyFraction=70
-XX:+UseCMSInitiatingOccupancyOnly
-Dsun.rmi.dgc.client.gcInterval=0x7FFFFFFFFFFFFFFE
-Dsun.rmi.dgc.server.gcInterval=0x7FFFFFFFFFFFFFFE
-cp /usr/local/app/conf:/usr/local/app/app.jar:/usr/local/app/lib/* -Xdebug
-Xrunjdwp:transport=dt_socket,address=8099,server=y,suspend=n
-Dvisualvm.display.name=App -XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=/usr/local/app/logs/
-XX:ErrorFile=/usr/local/app/logs/hs_err_pid%p.log
-Djgroups.tcpgossip.initial_host=localhost
-Dlog4j.hostname=host7.company.com com.company.app.service.App

ОБНОВЛЕНИЕ: Проблема все еще не решена. Я пробовал все: обновлял пакеты ОС и ядро, обновлял Java до последней версии Java 1.7.0_80, откатывал версию приложения, но безуспешно.

Я также проверил предыдущие журналы GC и обнаружил, что этот вопрос не был навсегда. Это началось около месяца назад после развертывания.

4b9b3361

ОТВЕТЫ

Ответ 1

Есть причина, почему это происходит. Кажется, что когда вы пытаетесь сделать heap dump, он вызывает метод dumpHeap(). Например, VisualVM запускает полный GC перед созданием дампа кучи.

Из документация:

void dumpHeap(String outputFile, boolean live) throws IOException

Сбрасывает кучу в файл выходного файла в том же формате, что и дамп кучи hprof. Если этот метод называется удаленно из другого процесса, выход дампа кучи записывается в файл с именем outputFile на машине, на которой запущена целевая виртуальная машина. Если outputFile является относительным путем, это относится к рабочему каталогу, в котором была запущена целевая виртуальная машина.

Параметры:

outputFile - системное имя файла

live - если true дамп только для живых объектов, то есть объектов, доступных из других

Почему?

Когда вы пытаетесь найти утечку памяти, вы не хотите получать объекты, которые не имеют ссылок (не собирались мусор).

Рекомендация

Я вижу довольно большую кучу, возможно, лучше использовать G1.

Первый фокус G1 - предоставить решение для пользователей, запускающих приложения, которым требуются большие кучи с ограниченной задержкой GC. Это означает, что размер кучи составляет около 6 ГБ или более, а стабильное и прогнозируемое время паузы ниже 0,5 секунды.

Взгляните на раздел рекомендаций также в документация.

Ответ 2

Я подозреваю, что из-за очень большой кучи в вашей заявке не было необходимости в сборке Major, но из-за очень большой кучи не было исчерпано ни Old Gen, ни Survivor Space.

Если вы считаете иначе (основная коллекция не была запущена, даже если выполнено какое-либо из условий), поделитесь своими заявлениями gclog.

С другой стороны: поскольку вы используете большую кучу, предпочтительнее G1GC.

EDIT:

-XX:CMSInitiatingOccupancyFraction=70 -XX:+UseCMSInitiatingOccupancyOnly

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

-XX:+UseCMSInitiatingOccupancyOnly предотвратить использование эвристик GC.

-XX:CMSInitiatingOccupancyFraction информирует Java VM о необходимости запуска CMS.

Вы настроили его как 70%. Если ваш OldGen [Max heap (29G) - новый Gen (3G)] касается 70% от предела, GC будет запущен. Как часть GC, запускается первый младший GC. Если второстепенный GC не выделяет достаточно места для выделения новых объектов на этом этапе, запускается Major GC или Full GC.

Посмотрите на статью для более подробной информации.

Я нашел еще один связанный вопрос SE: CMS сборщик мусора - когда он запустится?. Посмотрите на это тоже.

Ответ 3

CMS не разгружает классы по умолчанию в JDK 7.
Вы должны указать -XX:+CMSClassUnloadingEnabled или лучше переключиться на JDK 8.

BTW, если вы запустите jmap без аргумента live, он не будет вызывать Full GC перед созданием дампа кучи.

Ответ 4

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

  • Вероятное быстрое исправление: запись "CMS: abort preclean due to time" ваших журналов предполагает, что ваш сборщик CMS не настроен должным образом, чтобы выполнить эту работу до конечной фазы полного GC-фазы. В основном, что это сообщение журнала означает, что фаза preclean является тайм-аутом, и дальнейшие шаги сборщика CMS не могут выполняться. Значение по умолчанию для отмены преклинической фазы составляет 5 секунд, что, по-видимому, относится к вашим журналам. Подумайте об увеличении этого времени примерно до 10 секунд и наблюдайте, что происходит. Вы должны сделать это, добавив параметр -XX:CMSMaxAbortablePrecleanTime=10000. См. запись в блоге Misamitsu в параметре настройки CMSMaxAbortablePrecleanTime. Кроме того, на основе того, что я могу видеть из записи в блоге Stas по теме, единица измерения составляет миллисекунды, а не секунды.

Попробуйте эти долгосрочные вещи в долгосрочной перспективе:

  • Если вы можете, попробуйте сборщик G1GC. Вы используете Java 7, поэтому, если вы можете в вашей текущей среде, попробуйте. Это означало производительность с большими кучами.
  • Тот факт, что это произошло в результате развертывания и отката, не помогло мне:
    • Все ваше приложение (например, параметры настройки JVM) не записываются как часть вашего развертывания или...
    • Причина проблем с производительностью не связана с вашим приложением. Возможно, различия между двумя вашими хостами и несвязанным приложением на одном хосте, например, с другой антивирусной версией, усложняют работу сборщика мусора. Опять же, если можно, разверните точно такое же аппаратное и программное обеспечение.
  • Оцените, действительно ли вам нужна такая большая куча. Помните, чем крупнее куча, тем дольше собирается сборщик мусора, независимо от того, используете ли вы параллельный сборщик, такой как CMS.
  • У вас много параметров настройки, и я бы бросил вызов тому, что вам нужно большинство из них. Попробуйте запустить экспериментальный эксперимент, в котором вы просто стираете параметры -XX:NewSize=3000m, -XX:SurvivorRatio=8, -XX:CMSInitiatingOccupancyFraction=70, -XX:+UseCMSInitiatingOccupancyOnly, -Dsun.rmi.dgc.client.gcInterval=0x7FFFFFFFFFFFFFFE и -Dsun.rmi.dgc.server.gcInterval=0x7FFFFFFFFFFFFFFE и видите, улучшается ли ваша ситуация.

Я надеюсь, что это поможет, пожалуйста, прокомментируйте следующие вопросы, если это необходимо.