Проблемы с задержками, которые G1GC
Я столкнулся с продолжающимся увеличением пауз GC с алгоритмом G1GC. Задержки службы продолжают расти со временем.
Как только это произойдет, я перезапущу свою службу, и задержки вернутся к нормальной работе. Post startup, задержки снова продолжают увеличиваться с течением времени.
Во время запуска задержка службы составляет около 200 мс, но в течение 24 часов они поднимаются до 350 мс и продолжают расти линейным образом.
Увеличение латентности обслуживания соответствует увеличению показателей GarbageCollection.
Технические характеристики
Я запускаю java-приложение (JDK-8) на M4-2X больших блоках EC2 с 50 активными потоками в ящике. Сервис работает на куче 12 ГБ. Средняя латентность запроса составляет около 250 мс, а скорость входящих запросов составляет около 20 в секунду за каждый поле.
Конфигурации G1G1
<jvmarg line="-Xms12288M"/>
<jvmarg line="-Xmx12288M"/>
<jvmarg line="-verbose:gc" />
<jvmarg line="-XX:+UseG1GC"/>
<jvmarg line="-XX:+PrintGCDetails" />
<jvmarg line="-XX:+PrintGCTimeStamps" />
<jvmarg line="-XX:+PrintTenuringDistribution" />
<jvmarg line="-XX:+PrintGCApplicationStoppedTime" />
<jvmarg line="-XX:MaxGCPauseMillis=250"/>
<jvmarg line="-XX:ParallelGCThreads=20" />
<jvmarg line="-XX:ConcGCThreads=5" />
<jvmarg line="-XX:-UseGCLogFileRotation"/>
GC logs
79488.355: Total time for which application threads were stopped: 0.0005309 seconds, Stopping threads took: 0.0000593 seconds
79494.559: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 369098752 bytes, new threshold 15 (max 15)
- age 1: 64725432 bytes, 64725432 total
- age 2: 8867888 bytes, 73593320 total
- age 3: 2503592 bytes, 76096912 total
- age 4: 134344 bytes, 76231256 total
- age 5: 3729424 bytes, 79960680 total
- age 6: 212000 bytes, 80172680 total
- age 7: 172568 bytes, 80345248 total
- age 8: 175312 bytes, 80520560 total
- age 9: 282480 bytes, 80803040 total
- age 10: 160952 bytes, 80963992 total
- age 11: 140856 bytes, 81104848 total
- age 12: 153384 bytes, 81258232 total
- age 13: 123648 bytes, 81381880 total
- age 14: 76360 bytes, 81458240 total
- age 15: 63888 bytes, 81522128 total
, 2.5241014 secs]
[Parallel Time: 2482.2 ms, GC Workers: 20]
[GC Worker Start (ms): Min: 79494558.9, Avg: 79494567.4, Max: 79494602.1, Diff: 43.2]
[Ext Root Scanning (ms): Min: 0.0, Avg: 140.9, Max: 2478.3, Diff: 2478.3, Sum: 2818.8]
[Update RS (ms): Min: 0.0, Avg: 5.3, Max: 41.9, Diff: 41.9, Sum: 106.9]
[Processed Buffers: Min: 0, Avg: 23.2, Max: 80, Diff: 80, Sum: 465]
[Scan RS (ms): Min: 0.1, Avg: 0.2, Max: 0.4, Diff: 0.3, Sum: 4.1]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.4]
[Object Copy (ms): Min: 0.0, Avg: 41.9, Max: 68.7, Diff: 68.7, Sum: 837.9]
[Termination (ms): Min: 0.0, Avg: 2282.3, Max: 2415.8, Diff: 2415.8, Sum: 45645.3]
[Termination Attempts: Min: 1, Avg: 21.5, Max: 68, Diff: 67, Sum: 430]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.2, Diff: 0.1, Sum: 1.0]
[GC Worker Total (ms): Min: 2435.8, Avg: 2470.7, Max: 2482.0, Diff: 46.2, Sum: 49414.5]
[GC Worker End (ms): Min: 79497037.9, Avg: 79497038.1, Max: 79497041.0, Diff: 3.1]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.9 ms]
[Other: 40.9 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 37.7 ms]
[Ref Enq: 0.8 ms]
[Redirty Cards: 0.4 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.1 ms]
[Free CSet: 1.3 ms]
[Eden: 5512.0M(5512.0M)->0.0B(4444.0M) Survivors: 112.0M->128.0M Heap: 8222.2M(12.0G)->2707.5M(12.0G)]
[Times: user=19.63 sys=0.18, real=2.53 secs]
79497.083: Total time for which application threads were stopped: 2.5252654 seconds, Stopping threads took: 0.0000914 seconds
Я ищу некоторую помощь с конфигурациями GC. На основе моего чтения я планирую увеличить количество параллельных потоков до 32, установить G1HeapRegionSize на 16M и установить ConcGCThreads = 8.
Mixed Concurrent Mark Remark Cleanup initial-mark Young GC Total
Count 14 4 4 4 4 263 293
Total GC Time 4 sec 120 ms 0 1 sec 100 ms 70 ms 980 ms 1 min 8 sec 10 ms 1 min 14 sec 280 ms
Avg GC Time 294 ms 0 275 ms 17 ms 245 ms 259 ms 254 ms
Avg Time std dev 127 ms 0 73 ms 4 ms 73 ms 63 ms 79 ms
Min/Max Time 0 / 560 ms 0 / 0 0 / 400 ms 0 / 20 ms 0 / 340 ms 0 / 620 ms 0 / 620 ms
Avg Interval Time 2 min 55 sec 119 ms 12 min 32 sec 443 ms 12 min 32 sec 443 ms 12 min 32 sec 449 ms 12 min 32 sec 423 ms 13 sec 686 ms 51 sec 887 ms
GC Причины
Cause Count Avg Time Max Time Total Time Time %
G1 Evacuation Pause 263 259 ms 560 ms 1 min 8 sec 50 ms 91.61%
GCLocker Initiated GC 15 272 ms 400 ms 4 sec 80 ms 5.49%
Others 12 n/a n/a 1 sec 250 ms 1.68%
G1 Humongous Allocation 3 300 ms 340 ms 900 ms 1.21%
Total 293 n/a n/a 1 min 14 sec 280 ms 99.99%
Резюме по удержанию
Desired Survivor Size: 448.0 mb,
Max Threshold: 15
Age Survival Count Average size (kb) Average Total 'To' size (kb)
age 1 281 54856.84 54856.84
age 2 273 32935.6 89227.65
age 3 258 29812.41 122175.68
age 4 235 28499.48 158266.46
age 5 214 27909.13 196528.23
age 6 192 26896.33 237892.45
age 7 180 25759.58 272516.81
age 8 174 23565.21 299092.37
age 9 166 21745.62 320927.73
age 10 149 19323.6 340228.24
age 11 125 17400.14 357569.6
age 12 96 13995.26 372030.12
age 13 55 10909.19 378053.14
age 14 38 10197.95 389146.13
age 15 22 5996.65 395657.37
Ответы
Ответ 1
Первая точка
Вам нужно проверить наличие утечки в приложении.
Но в G1GC может быть один параметр, который вы можете проанализировать:
Humongous Objects
В этот момент большая часть функциональности и архитектуры G1GC была сброшена, , за исключением самой большой слабости/сложности, объекта Humongous. Как упоминалось ранее, любое выделение данных ≥ G1HeapRegionSize/2 считается объектом Humongous, который выделяется из смежных областей свободного пространства, которые затем добавляются к Tenured. Пусть пробегут некоторые основные характеристики и как они влияют на обычный жизненный цикл GC. Следующее обсуждение объектов Humongous даст представление о недостатках объектов Humongous, таких как:
Increase the risk of running out of Free space and triggering a Full GC
Increase overall time spent in STW
Любые объекты выделяются из свободного пространства. Сбой распределения вызывает события GC. Если сбой распределения из Free space запускает GC, GC-событие будет Full GC, что очень нежелательно в большинстве случаев. Чтобы избежать полномасштабных событий GC в приложении с большим количеством объектов Humongous, необходимо обеспечить, чтобы пул свободного пространства был достаточно большим по сравнению с Eden, который Eden всегда будет заполнять первым. Обычно обычно оказывается слишком осторожным, и приложение заканчивается в состоянии, когда Free ram пул достаточно велик и никогда не используется полностью, что по определению направляет RAM.
Любые объекты освобождаются в конце MPCMC
До тех пор, пока вокруг Oracle JDK 8u45, было правдой, что объекты Humongous собирались только в конце прогонов MPCMC. В примечаниях к выпуску для версий Oracle 8u45-8u65 есть несколько коммитов, указывающих на некоторые, но не все, объекты Humongous собираются во время событий Minor.
Итак, вы можете попробовать, обновив последнюю версию java.
Собственные объекты, которые собираются только в конце MPCMC, увеличат требования к зарезервированному свободному пространству или, скорее всего, вызовут полный GC.
Поиск того, как много гуманного объекта:
Шаг 1. выполните следующую команду на вашем gc.log
Команда 1:
grep "source: concurrent humongous allocation" /tmp/gc.log | sed 's/.*allocation request: \([0-9]*\) bytes.*/\1/' > humoungous_humongoud_size.txt
Команда 2:
awk -F',' '{sum+=$1} END{print sum;}' humoungous_humongoud_size.txt
Он предоставит вам размер огромных объектов, сгенерированных в моем приложении.
Но, наконец, если ваше приложение имеет утечки памяти, вы должны решить это.
Ответ 2
Это молодая коллекция, и почти все умирает молодым, так что в отличие от комментариев выше этого, похоже, не проблема с заполнением старого поколения.
[Ext Root Scanning (ms): Min: 0.0, Avg: 140.9, Max: 2478.3, Diff: 2478.3, Sum: 2818.8]
В основном он тратит большую часть времени на сканирование корней GC, а остальные фазы затем удерживаются в ожидании завершения этой фазы.
У вас много потоков (вы упоминаете только активные)? Или ваше приложение пропускает классы или динамически генерирует все больше байт-кода?
Приложение генерирует много классов динамически для каждого вызова службы, и учитывая объем вызовов, я подозреваю, что эти классы могут быть проблемой, но не уверены, как его разрешить.
Сначала вам нужно выяснить, собираются ли эти созданные классы вообще во время коллекций старого поколения. Если нет, у вас есть утечка и вам необходимо исправить ваше приложение. Если они накапливаются, но собираются в конечном итоге, вам нужно только собирать более старое поколение, например. уменьшая размер молодого поколения (что оказывает большее давление на старый ген) или уменьшает IHOP.
Ответ 3
Если бы я был на вашем месте, я бы это сделал.
- Получите журналы GC в течение нескольких дней и загрузите его в http://gceasy.io/, чтобы оценить, как растет память.
- Временно измените механизм сбора мусора из G1 в параллельный сборщик. Я предлагаю перейти к параллельному сборщику, поскольку он распределяет память линейным способом и относительно легко проверить, есть ли у вас утечка памяти. Вы также получаете хорошее сравнение с G1. Это не означает, что вам придется постоянно перемещаться параллельно, это просто для временного сравнения.
- Если куча постоянно растет линейно, без сбора мусора, то это определенно утечка памяти, и вам придется ее найти.
- Если вы не видите никаких признаков утечки памяти, вы можете подумать о настройке настроек сбора мусора.
Тщательный сборщик мусора G1 в соответствии с вашим сервисом очень важен. G1 без каких-либо настроек может быть очень плохой для некоторых сервисов, подобных нам, что намного хуже, чем параллельный коллектор. Но теперь с конкретными настройками он теперь работает лучше на нашем сервере, который имеет 64 ядра и 256 ГБ оперативной памяти.
Ответ 4
Прежде всего, у вас большое время потрачено на копирование объектов между поколениями.
G1 Пауза эвакуации 263 259 мс 560 мс 1 мин 8 с 50 мс 91,61%
В соответствии с этим
[Eden: 5512.0M (5512.0M) → 0.0B (4444.0M) Выжившие: 112.0M- > 128.0M Куча: 8222.2M (12.0G) → 2707.5M (12.0G)]
[Object Copy (ms): Min: 0.0, Avg: 41.9, Max: 68.7, Diff: 68.7, Sum: 837.9]
[Обновить RS (ms): Min: 0.0, Avg: 5.3, Max: 41.9, Diff: 41.9, Sum: 106.9]
Ref Proc: 37,7 мс
[Ext Root Scanning (ms): Min: 0.0, Avg: 140.9, Max: 2478.3, Diff: 2478.3, Sum: 2818.8]
Это все об управлении объектами между регионами. Похоже, у вас много живых объектов времени, но тратите много времени на управление объектами между регионами. Постарайтесь играть с Young Gen размером. С одной стороны вы можете увеличить его, поэтому вы будете тратить меньше времени на копирование объектов. Это может увеличить время анализа корней. Если большинство объектов мертво, все будет в порядке. Но если нет, вы должны наоборот уменьшить Young Size, тогда G1 будет вызываться чаще, но тратит меньше времени на один вызов, что обеспечивает более прогностическое поведение и латентность. Поскольку мы видим, что самое большое время тратится на анализ корней, я бы начал с уменьшения размера Young Gen до 3 ГБ, чтобы узнать, что произойдет.
Второй -
Termination (ms): Min: 0.0, Avg: 2282.3, Max: 2415.8, Diff: 2415.8, Sum: 45645.3]
Ваш G1 тратит много времени на процесс завершения, где он пытается завершить работу с нитями, но до этого он проверяет все очереди и выполняет задачи.
Вы могли видеть, что есть много попыток воровства:
Прекращение Попытки: Мин: 1, Среднее: 21,5, Макс: 68, Дифф: 67, Сумма: 430
21.5 попыток за один рабочий поток это не бит. Если рабочий поток успешно украл задачи, он будет продолжен. У вас здесь большой concurrency, и я полагаю, вы могли бы уменьшить количество потоков GC.
p.s. Чтобы выбрать GC, вы должны использовать:
- Параллельный GC, если не подходит, то...
- G1, если не подходит, тогда...
- настроенная CMS с ParNew.
Если бы я был вами, я бы использовал CMS с ParNew на вашем месте, чтобы обеспечить хорошую задержку для этого сценария.
См. также понимание журналов G1
