☰

GC берет большую паузу и ParNew (продвижение не удалось)

tag-icon • tag-icon java garbage-collecting
GC берет большую паузу и ParNew (продвижение не удалось)

Одно из наших приложений Java делает большую паузу при выполнении сборки мусора, похоже, из-за «ParNew (продвижение не удалось)», это занимает много времени.

Java-версия:

$ java -version
java version "1.6.0_21"
Java(TM) SE Runtime Environment (build 1.6.0_21-b06)
Java HotSpot(TM) 64-Bit Server VM (build 17.0-b16, mixed mode)

Настройки ГХ:

JAVA_OPTS="$JAVA_OPTS -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTenuringDistribution -Dsun.rmi.dgc.client.gcInterval=86400000 -Dsun.rmi.dgc.server.gcInterval=86400000 -verbose:gc -Xloggc:/path/to/gc/gc.log"
JAVA_OPTS="$JAVA_OPTS  -XX:NewSize=5g -XX:MaxNewSize=5g -Xms10g -Xmx10g -XX:PermSize=512m -XX:MaxPermSize=512m -XX:SurvivorRatio=30 -XX:TargetSurvivorRatio=90 -XX:MaxTenuringThreshold=15"
# Parallel setting
JAVA_OPTS="$JAVA_OPTS -XX:+UseParNewGC -XX:ParallelGCThreads=16"
# CMS setting
JAVA_OPTS="$JAVA_OPTS  -XX:+UseConcMarkSweepGC -XX:+CMSParallelRemarkEnabled -XX:+CMSCompactWhenClearAllSoftRefs -XX:CMSInitiatingOccupancyFraction=85 -XX:+CMSScavengeBeforeRemark -XX:+CMSConcurrentMTEnabled -XX:ParallelCMSThreads=2"

Вот вывод gc.log для нескольких длинных пауз:

2015-06-04T10:02:28.988+0000: 129998.706: [GC[YG occupancy: 1904924 K (5079040 K)]2015-06-04T10:02:28.988+0000: 129998.706: [GC 129998.706: [ParNew (promotion
 failed)
Desired survivor size 150994944 bytes, new threshold 10 (max 15)
- age   1:   39557704 bytes,   39557704 total
- age   2:   23752968 bytes,   63310672 total
- age   3:   11024200 bytes,   74334872 total
- age   4:   10529816 bytes,   84864688 total
- age   5:    9602712 bytes,   94467400 total
- age   6:    9621976 bytes,  104089376 total
- age   7:   27355240 bytes,  131444616 total
- age   8:    6326944 bytes,  137771560 total
- age   9:    7153592 bytes,  144925152 total
- age  10:    6944200 bytes,  151869352 total
- age  11:    7226592 bytes,  159095944 total
- age  12:    6674048 bytes,  165769992 total
: 1904924K->1904924K(5079040K), 84.3892780 secs] 6687900K-     >7143259K(10321920K), 84.3894730 secs] [Times: user=241.33 sys=9.83,  real=84.39 secs]
130083.096: [Rescan (parallel) , 1.0518870 secs]130084.148: [weak refs     processing, 0.0056350 secs] [1 CMS-remark: 5238334K(5242880K)]   7143259K(10321920K), 85.
4473940 secs] [Times: user=249.44 sys=10.00, real=85.44 secs]
Total time for which application threads were stopped: 85.4485540 seconds

2015-06-09T01:36:38.354+0000: 531648.072: [GC[YG occupancy: 3444075 K (5079040 K)]2015-06-09T01:36:38.354+0000: 531648.072: [GC 531648.072: [ParNew (promotion
 failed)
Desired survivor size 150994944 bytes, new threshold 6 (max 15)
- age   1:  118719600 bytes,  118719600 total
- age   2:   20791640 bytes,  139511240 total
- age   3:    2411752 bytes,  141922992 total
- age   4:    3146888 bytes,  145069880 total
- age   5:    3595160 bytes,  148665040 total
- age   6:    3950560 bytes,  152615600 total
- age   7:    2455960 bytes,  155071560 total
- age   8:    2780536 bytes,  157852096 total
- age   9:    2346000 bytes,  160198096 total
- age  10:    2952600 bytes,  163150696 total
- age  11:    1078304 bytes,  164229000 total
- age  12:    1857992 bytes,  166086992 total
- age  13:    1093752 bytes,  167180744 total
: 3444075K->3444075K(5079040K), 53.3528910 secs] 7494225K->8679897K(10321920K), 53.3531460 secs] [Times: user=168.75 sys=10.21, real=53.36 secs]
531701.426: [Rescan (parallel) , 1.2041260 secs]531702.630: [weak refs processing, 0.0002920 secs] [1 CMS-remark: 5235821K(5242880K)] 8679897K(10321920K), 54.
5583950 secs] [Times: user=178.02 sys=10.43, real=54.57 secs]
Total time for which application threads were stopped: 54.5615990 seconds
2015-06-09T01:37:32.913+0000: 531702.631: [CMS-concurrent-sweep-start]


2015-06-10T12:58:53.687+0000: 658983.405: [GC 658983.405: [ParNew (promotion failed)
Desired survivor size 150994944 bytes, new threshold 11 (max 15)
- age   1:   62173384 bytes,   62173384 total
- age   2:    4913808 bytes,   67087192 total
- age   3:   10095568 bytes,   77182760 total
- age   4:   12476376 bytes,   89659136 total
- age   5:    8521376 bytes,   98180512 total
- age   6:     985064 bytes,   99165576 total
- age   7:    8824120 bytes,  107989696 total
- age   8:    9991888 bytes,  117981584 total
- age   9:   23527832 bytes,  141509416 total
- age  10:    5438928 bytes,  146948344 total
- age  11:    6171880 bytes,  153120224 total
- age  12:    6983376 bytes,  160103600 total
- age  13:    1196080 bytes,  161299680 total
- age  14:    5357040 bytes,  166656720 total
: 5079040K->5079040K(5079040K), 31.3569910 secs]659014.762: [CMS: 5239285K->5242879K(5242880K), 11.5386160 secs] 9441788K->5341454K(10321920K), [CMS Perm : 42
6919K->426638K(524288K)], 42.8959280 secs] [Times: user=120.92 sys=7.35, real=42.90 secs]
Total time for which application threads were stopped: 42.8996760 seconds
Application time: 0.0001030 seconds
2015-06-10T12:59:36.587+0000: 659026.305: [GC [1 CMS-initial-mark: 5242879K(5242880K)] 5343035K(10321920K), 0.0946190 secs] [Times: user=0.09 sys=0.00, real=0.09 secs]
Total time for which application threads were stopped: 0.0979600 seconds
2015-06-10T12:59:36.682+0000: 659026.400: [CMS-concurrent-mark-start]
Application time: 0.2920200 seconds

Как мне устранить эту неполадку, если что-то не так в настройках GC?

решение1

Обновление до новой версии Java 1.6 может помочь. Некоторые исправления связаны с поведением GC.

Похоже, новый размер чрезвычайно чрезмерен. У вас обычно есть несколько Мб, переживающих GC нового поколения, и это, похоже, предназначено для старого поколения. Попробуйте уменьшить до -XX:NewSizeзначения от 128 до 512 м. Вероятно, не повредит удалить настройку -XX:MaxNewSize=5g.

Эти настройки, вероятно, вызывают проблему -XX:SurvivorRatio=30 -XX:TargetSurvivorRatio=90 -XX:MaxTenuringThreshold=15". Попробуйте просто установить -XX:SurvivorRatio=32. Эти настройки заставят процедуры GC постоянно пытаться изменить размер коэффициента выживших. Вы получаете коэффициенты выживших около 10–15. Следите за заполненностью коэффициента выживших и корректируйте так, чтобы он был близок к полному.

Вероятно, вам нужна -XX:MaxTenuringThresholdнастройка 4 или меньше. Чем больше объектов у вас в новой генерации во время параллельной сборки мусора, тем медленнее будет. Вам нужно, чтобы новая генерация была как можно ближе к пустой во время первоначальной маркировки. По моим тестам все объекты в новой генерации считаются живыми во время параллельной маркировки. Поскольку время, затрачиваемое на процесс маркировки, пропорционально количеству живых объектов, это может быть серьезным штрафом. С более низкой настройкой вы можете увеличить коэффициент выживших.

Настройки -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime, как правило, загромождают журнал и могут не давать много полезной информации. Я бы их удалил.

Вы можете захотеть увеличить количество потоков, используемых для Concurrent GC. Рассмотрите 25% потоков CPU.

Рассмотрите возможность уменьшения -XX:CMSInitiatingOccupancyFractionдо диапазона от 70 до 75. Из-за размера выделенной памяти вам может подойти значение 85%. Если память станет слишком фрагментированной, вы получите длительную паузу, пока память будет уплотняться.

Рассмотрите возможность снижения общей памяти, указанной в -Xms -Xmx5g или 6g. Вы можете захотеть нацелиться на GC старого поколения каждые 1–4 часа. Если память выгружается между циклами GC, вам, возможно, придется подождать, пока она будет выгружена. Это может значительно увеличить время GC. Вам может потребоваться больше старого поколения для поддержки более низкой начальной занятости.

Связанный контент