95 последовательных полных сборов мусора, но без OOM. Как это могло случиться?

Question

Я устраняю неполадки в веб-приложении Java, которое некоторое время работает нормально, после чего куча внезапно достигает 100%, и это приводит к последовательным полным сборкам мусора, при этом почти не удаляется старый ген. Это, однако, не приводит к OOM с обычным сообщением java.lang.OutOfMemoryError: GC overhead limit exceeded. Как это могло произойти?

Вот 6 полных записей GC: * ​​1004 *

gc_20180423_1443.log.11.current:37491:2018-05-01T09:10:52.156+0000: 671212.664: [Full GC (Allocation Failure) 2018-05-01T09:10:52.156+0000: 671212.664: [CMS: 7077887K->7077887K(7077888K), 28.6425809 secs] 9043967K->9043787K(9043968K), [Metaspace: 75140K->75140K(1118208K)], 28.6428227 secs] [Times: user=28.63 sys=0.00, real=28.64 secs]
gc_20180423_1443.log.11.current:37510:2018-05-01T09:11:20.803+0000: 671241.311: [Full GC (Allocation Failure) 2018-05-01T09:11:20.803+0000: 671241.311: [CMS: 7077887K->7077888K(7077888K), 42.8881300 secs] 9043964K->9043856K(9043968K), [Metaspace: 75140K->75140K(1118208K)], 42.8883826 secs] [Times: user=42.85 sys=0.01, real=42.89 secs]
gc_20180423_1443.log.11.current:37529:2018-05-01T09:12:03.694+0000: 671284.201: [Full GC (Allocation Failure) 2018-05-01T09:12:03.694+0000: 671284.201: [CMS: 7077888K->7077888K(7077888K), 28.8305893 secs] 9043959K->9043845K(9043968K), [Metaspace: 75140K->75140K(1118208K)], 28.8308264 secs] [Times: user=28.83 sys=0.01, real=28.83 secs]
gc_20180423_1443.log.11.current:37548:2018-05-01T09:12:32.527+0000: 671313.035: [Full GC (Allocation Failure) 2018-05-01T09:12:32.527+0000: 671313.035: [CMS: 7077888K->7077887K(7077888K), 34.2235811 secs] 9043967K->9043802K(9043968K), [Metaspace: 75140K->75140K(1118208K)], 34.2238304 secs] [Times: user=34.22 sys=0.00, real=34.23 secs]
gc_20180423_1443.log.11.current:37567:2018-05-01T09:13:06.754+0000: 671347.261: [Full GC (Allocation Failure) 2018-05-01T09:13:06.754+0000: 671347.262: [CMS: 7077887K->7077887K(7077888K), 30.2722671 secs] 9043966K->9043854K(9043968K), [Metaspace: 75140K->75140K(1118208K)], 30.2725042 secs] [Times: user=30.27 sys=0.00, real=30.27 secs]
gc_20180423_1443.log.11.current:37586:2018-05-01T09:13:37.028+0000: 671377.536: [Full GC (Allocation Failure) 2018-05-01T09:13:37.028+0000: 671377.536: [CMS: 7077887K->7077887K(7077888K), 35.6276778 secs] 9043955K->9043843K(9043968K), [Metaspace: 75140K->75140K(1118208K)], 35.6278998 secs] [Times: user=35.61 sys=0.01, real=35.63 secs]

Согласно моим расчетам, общая продолжительность, основанная на журналах для этих 6 записей, составляет 164,872 с, из которых GC занимает 164,8583663 с, что составляет 99,99% времени в GC. Учитывая общую кучу 9043968K, выведите 2% до 180879,36K.

Общая куча, очищенная из журналов в этих 5 выполнениях, составляет 679 КБ (между вызовами), что намного меньше 2%, но OOM не выбрасывается.

Флаг -XX:-UseGCOverheadLimit не использовался.

Вот список параметров GC: * ​​1014 *

CommandLine flags: -XX:CICompilerCount=4 
-XX:CMSInitiatingOccupancyFraction=50 -XX:CMSMaxAbortablePrecleanTime=6000 
-XX:+CMSParallelRemarkEnabled -XX:+CMSScavengeBeforeRemark
-XX:ConcGCThreads=4 -XX:+CrashOnOutOfMemoryError -XX:GCLogFileSize=10485760 
-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/WORK/log/solr/solr.hprof 
-XX:InitialHeapSize=9663676416 -XX:LogFile=/WORK/log/solr/vm.log -XX:+LogVMOutput 
-XX:MaxHeapSize=9663676416 -XX:MaxNewSize=2415919104 -XX:MaxTenuringThreshold=8 
-XX:MinHeapDeltaBytes=196608 -XX:NewRatio=3 -XX:NewSize=2415919104
-XX:NumberOfGCLogFiles=20 -XX:OldPLABSize=16 -XX:OldSize=7247757312
-XX:OnOutOfMemoryError=/WORK/bin/oom.sh solr -XX:ParallelGCThreads=4
-XX:+ParallelRefProcEnabled -XX:PretenureSizeThreshold=67108864 -XX:+PrintGC 
-XX:+PrintGCApplicationStoppedTime -XX:+PrintGCDateStamps -XX:+PrintGCDetails 
-XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+PrintSafepointStatistics
-XX:PrintSafepointStatisticsCount=1 -XX:+PrintTenuringDistribution
-XX:+SafepointTimeout -XX:SafepointTimeoutDelay=500 -XX:SurvivorRatio=4
-XX:TargetSurvivorRatio=90 -XX:ThreadStackSize=256 
-XX:+UnlockDiagnosticVMOptions -XX:-UseBiasedLocking 
-XX:+UseCMSInitiatingOccupancyOnly -XX:+UseCompressedClassPointers
-XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseGCLogFileRotation
-XX:+UseParNewGC 

Версия JDK openjdk-1.8.0_151

Пожалуйста, дайте мне знать, если вы заметили ошибку в моих вычислениях или мое понимание правила java.lang.OutOfMemoryError: GC overhead limit exceeded, которое выдается, когда более 98% общего времени тратится на сборку мусора и менее 2% кучи восстанавливается.

Любые указатели очень ценятся. Спасибо!

Answer 1

Что такое последовательные полные ГХ?

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

Heap graph generated by GCeasy tool – showing consecutive full GC

Как решать последовательные полные сборы мусора?

Последовательные полные GC могут быть решены с помощью одного из следующих решений:

1. Увеличение размера кучи JVM
2. Увеличение размера Пермского генерала / метапространства
3. Добавить больше экземпляров JVM

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

Что вызывает последовательные полные сборы?