☰

GC 长时间暂停和 ParNew（升级失败）

tag-icon • tag-icon java garbage-collecting
GC 长时间暂停和 ParNew（升级失败）

我们的一个 java 应用程序在执行 GC 时会出现很长的暂停，似乎是因为“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)

GC设置：

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 中，只有几 MB 的空间幸存下来，而这似乎注定要留给老一代。尝试将大小降低-XX:NewSize到 128m 到 512m 之间。删除该-XX:MaxNewSize=5g设置可能不会有什么坏处。

这些设置可能会导致问题-XX:SurvivorRatio=30 -XX:TargetSurvivorRatio=90 -XX:MaxTenuringThreshold=15"。尝试设置-XX:SurvivorRatio=32。这些设置将导致 GC 例程不断尝试调整幸存者比率。您获得的幸存者比率约为 10 到 15。监控幸存者占用率并进行调整，使其接近满载。

您可能希望将-XX:MaxTenuringThreshold设置设为 4 或更低。在并发 GC 期间，新生代中的对象越多，速度就越慢。您希望在初始标记期间，新生代尽可能接近空。根据我的测试，在并发标记过程中，新生代中的所有对象都被视为活动对象。由于标记过程所花费的时间与活动对象的数量成正比，因此这可能是一个沉重的惩罚。使用较低的设置，您可能能够提高幸存者比率。

该设置-XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime往往会使日志变得混乱，可能不会产生太多有用的信息。我会删除它们。

您可能需要增加用于并发 GC 的线程数。考虑 25% 的 CPU 线程。

考虑将这个值降低-XX:CMSInitiatingOccupancyFraction到 70 到 75 之间。考虑到内存分配的大小，85% 可能就够了。如果内存过于分散，在内存压缩时会遇到长时间的停顿。

考虑将指定的总内存降至-Xms -Xmx5g 或 6g。您可能希望每 1 到 4 小时进行一次旧代 GC。如果内存在 GC 周期之间被调出，您可能需要等待它被调入。这会显著增加 GC 时间。您可能需要更多的旧代来支持较低的启动占用率。

相关内容