Java HotSpot极长时间的young区收集

Question

这是一个长时间运行的服务器应用程序，启动后会产生很多短暂的垃圾，几乎没有老年代。大部分时间，年轻代的垃圾收集速度很快，即使达到10 GB，因为几乎全部都是垃圾，但我们偶尔会看到一些异常情况。可能的提示是，在更高负载的机器上运行了一个配置类似的较低负载的服务器，但内存少了12 GB，我们在那里没有看到这种模式。

以下是来自GC日志的片段。由于系统时间很高，是否可以安全地说它花费了全部时间去执行GC工作（而不是等待线程达到安全点）？

java -Xms20g -Xmx20g -Xloggc:"./logs/gc.log" -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:NewRatio=1 -XX:+DisableExplicitGC -XX:+UseSpinning -XX:PreBlockSpin=1000 -XX:-UseCounterDecay -XX:+UseTLAB -XX:+TieredCompilation -XX:ReservedCodeCacheSize=512m

2013年12月13日14:04:50.388+0000: 56748.603: [GC [PSYoungGen: 10363808K->1248K(10421824K)] 10569323K->207003K(20907584K), 0.0035110秒] [Times: user=0.03 sys=0.00, real=0.00秒]

2013年12月13日14:17:32.245+0000: 57510.460: [GC [PSYoungGen: 10363808K->1600K(10435072K)] 10569563K->207563K(20920832K), 0.0038460秒] [Times: user=0.04 sys=0.00, real=0.01秒]

2013年12月13日14:29:08.572+0000: 58206.787: [GC [PSYoungGen: 10381824K->1408K(10430912K)] 10587787K->207875K(20916672K), 0.0045710秒] [Times: user=0.04 sys=0.00, real=0.01秒]

2013年12月13日14:36:25.176+0000: 58643.391: [GC [PSYoungGen: 10381632K->1600K(10442432K)] 10588099K->208371K(20928192K), 0.0040800秒] [Times: user=0.03 sys=0.00, real=0.00秒]

2013年12月13日14:44:04.409+0000: 59102.624: [GC [PSYoungGen: 10397120K->1600K(10438848K)] 10603891K->208715K(20924608K), 14.7387710秒] [Times: user=0.00 sys=143.05, real=14.74秒]

2013年12月13日14:52:50.287+0000: 59628.502: [GC [PSYoungGen: 10397120K->11488K(10446720K)] 10604235K->218819K(20932480K), 0.0127280秒] [Times: user=0.11 sys=0.00, real=0.01秒]

2013年12月13日14:59:34.934+0000: 60033.149: [GC [PSYoungGen: 10418208K->1536K(10445760K)] 10625539K->218931K(20931520K), 211.1968100秒] [Times: user=0.00 sys=2067.08, real=211.16秒]

2013年12月13日15:12:04.478+0000: 60782.693: [GC [PSYoungGen: 10408256K->15136K(10448064K)] 10625651K->232723K(20933824K), 0.0147670秒] [Times: user=0.00 sys=0.12, real=0.01秒]

2013年12月13日15:23:02.123+0000: 61440.338: [GC [PSYoungGen: 10426912K->12672K(10448768K)] 10644499K->232635K(20934528K), 0.0141040秒] [Times: user=0.00 sys=0.12, real=0.02秒]

2013年12月13日15:31:09.119+0000: 61927.334: [GC [PSYoungGen: 10424448K->5280K(10452160K)] 10644411K->232907K(20937920K), 0.8134440秒] [Times: user=1.22 sys=6.30, real=0.82秒]

2013年12月13

上述服务器的规格为双4核X5570，内存为48GB。HTOP显示已使用15GB，其余内容已被缓存，应用程序在任何时候仅使用略超过10GB（tenured很小）。这让我认为这不是分页问题。

我提到的另一个服务器是双8核E5-2690，内存为32GB。两台服务器都在Fedora上运行jre 1.7.0_25，尽管上述服务器使用的是非常旧的版本。

- gbasin

Answer 1

这么高的sys时间是不寻常的。是否可能与系统中的其他应用程序/活动有干扰作用？

我认为您还应收集其他系统统计信息 - vmstat，netstat，iostat，mpstat，以排除任何干扰或GC时间对系统活动的影响。将它们与YounGen阶段相关联，查看在这些长时间的YounGen暂停期间是否有任何峰值。

- Aleš

---

用户时间为0.00，因此看起来它正在等待系统资源，而不是实际执行GC工作... - Aleš

是的，可能需要几天时间。我忘了提到我们正在绑定 netsniff-ng 到一个 CPU(-b 1)，收集所有的网络流量。该应用程序也在从相同的套接字读取并处理一些工作。它平均大约是10mb/s。也许应用程序的一个线程恰好在 netsniff CPU 上，在这些长时间 GC 的重要时刻，等待该线程达到安全点会被显示为 sys 时间？ - gbasin

也许可以尝试禁用netsniff-ng。如果它阻塞了JVM，应该会在vmstats/mpstat中显示出来，例如上下文切换的数量增加/减少等。您还可以开始监视safepoints，有一个标志可以使用……但我不确定其性能影响……因为有很多这样的点，可能会相当沉重。 - Aleš

还有，CPU上的中断是什么？当netsniff启动时是否会出现任何峰值/下降？它在哪个CPU上？如果它和GC线程使用的是同一个CPU呢？也许您可以为JVM绑定CPU，并为netsniff绑定不同的CPU，这样它们就不会相互干扰...只是为了检查是否有任何干扰。 - Aleš

应该在接下来的一周左右推出一个垃圾较少的版本以在该盒子上运行，并查看其是否持续存在（我认为它会）。然后，我将尝试将线程绑定到netsniff的CPU之外。 Netsniff始终在运行（平均几MB / s），尽管负载始终相当低。 - gbasin