Java 8 young gc花费超过1s，如何减少新生代gc时间

Question

问题描述

我们的 Java 应用程序在 docker 中运行，它使用 Java 8 和 6C、8g。

垃圾收集算法使用 parNew + CMS，但几乎不会触发 olg gen gc。

框架:Spring + mybatis + dubbo + RocketMQ。

这是 JVM 参数:

-server -Xmx5g -Xms5g -Xmn1g -XX:MetaspaceSize=512m -XX:MaxMetaspaceSize=512m -Xss256k -XX:SurvivorRatio=8 -XX:+PrintGCDetails -Xloggc:/opt/apps/logs/gc.log -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTime -XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1 -XX:+PrintReferenceGC -XX:+UnlockDiagnosticVMOptions -XX:-DisplayVMOutput -XX:+LogVMOutput -XX:LogFile=/opt/apps/logs/safepoint.log -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=70 -XX:+CMSParallelRemarkEnabled -XX:+UseCMSCompactAtFullCollection -XX:+UseFastAccessorMethods -XX:+UseCMSInitiatingOccupancyOnly -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/opt/apps/logs

我花了两个星期的时间来解决这个问题，但无法找出原因。首先，我打开GC日志和安全点日志，怀疑安全点可能是原因。但我发现旋转时间+出 block 时间非常短。仅当发生young gc时，vmop时间几乎与young gc停止时间相同。

然后我检查 FinalReference 集合，并添加 PrintReferenceGC。也很短。

这是GC日志

2019-09-20T03:03:37.816+0800: 23271.179: [GC (Allocation Failure) 2019-09-20T03:03:37.818+0800: 23271.180: [ParNew2019-09-20T03:03:39.394+0800: 23272.756: [SoftReference, 0 refs, 0.0000626 secs]2019-09-20T03:03:39.394+0800: 23272.756: [WeakReference, 92 refs, 0.0000400 secs]2019-09-20T03:03:39.394+0800: 23272.756: [FinalReference, 55 refs, 0.0001404 secs]2019-09-20T03:03:39.394+0800: 23272.756: [PhantomReference, 0 refs, 0 refs, 0.0000298 secs]2019-09-20T03:03:39.394+0800: 23272.756: [JNI Weak Reference, 0.0000552 secs]: 845514K->6643K(943744K), 1.5767273 secs] 1160791K->322039K(5138048K), 1.5784758 secs] [Times: user=5.21 sys=0.17, real=1.57 secs] 2019-09-20T03:03:39.396+0800: 23272.758: Total time for which application threads were stopped: 1.5826799 seconds, Stopping threads took: 0.0005805 seconds

这是安全点日志

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count 23271.176: GenCollectForAllocation [ 1699 0 2 ] [ 0 0 0 2 1578 ] 0

Answer 1

从年轻回收后的剩余堆占用情况可以看出，应用程序的实时集大小(包括年轻和旧对象)似乎< 300MB。您的总堆大小为 5GB，因此有很大的喘息空间。

由于存在喘息空间，并且年轻一代的暂停时间是一个问题，您可以尝试缩小年轻一代，这可能会稍微提高保有率，但 CMS 老一代收集器应该能够跟上。

从您提供的 GC 日志中:

2019-09-20T07:56:55.968+0800: 40869.330: [GC (Allocation Failure) 2019-09-20T07:56:55.969+0800: 40869.331: [ParNew2019-09-20T07:56:56.006+0800: 40869.368: [SoftReference, 0 refs, 0.0000588 secs]2019-09-20T07:56:56.006+0800: 40869.368: [WeakReference, 114 refs, 0.0000369 secs]2019-09-20T07:56:56.006+0800: 40869.368: [FinalReference, 22 refs, 0.0000404 secs]2019-09-20T07:56:56.006+0800: 40869.368: [PhantomReference, 0 refs, 0 refs, 0.0000298 secs]2019-09-20T07:56:56.006+0800: 40869.368: [JNI Weak Reference, 0.0000626 secs]: 842095K->3179K(943744K), 0.0378130 secs] 1170641K->331912K(5138048K), 0.0394628 secs] [Times: user=0.70 sys=0.42, real=0.04 secs] 
2019-09-20T07:58:44.545+0800: 40977.907: [GC (Allocation Failure) 2019-09-20T07:58:44.545+0800: 40977.908: [ParNew2019-09-20T07:58:45.798+0800: 40979.160: [SoftReference, 0 refs, 0.0000641 secs]2019-09-20T07:58:45.798+0800: 40979.160: [WeakReference, 116 refs, 0.0000436 secs]2019-09-20T07:58:45.798+0800: 40979.160: [FinalReference, 14 refs, 0.0000217 secs]2019-09-20T07:58:45.798+0800: 40979.160: [PhantomReference, 0 refs, 0 refs, 0.0000293 secs]2019-09-20T07:58:45.798+0800: 40979.160: [JNI Weak Reference, 0.0000510 secs]: 842091K->3159K(943744K), 1.2526309 secs] 1170824K->331976K(5138048K), 1.2541209 secs] [Times: user=6.73 sys=0.66, real=1.26 secs] 

这两个集合执行相似的工作量，但需要 10 倍的 CPU 周期和 30 倍的实际时间。这通常表明 JVM 外部的原因，即其他进程或(如 Alexey 建议的)同级 VM 争用 CPU 或内存带宽资源。 CPU 热节流也可能是一个问题，但这在服务器环境中不太常见。