Java 8 young gc cost 超过1s，如何减少new generation gc time
Java 8 young gc cost more than 1s, how to reduce new generation gc time
问题描述
我们的 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日志和安全点日志，怀疑是安全点导致的。但是我发现旋转时间+阻塞时间非常短。只有在young gc发生的时候，vmop的时间和young gc停止的时间差不多。
然后我检查 FinalRefence 集合，并添加 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
从年轻代回收后的剩余堆占用率可以看出，您的应用程序的活动集大小（包括新旧对象）似乎小于 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 热节流也可能是一个问题，但这在服务器环境中不太常见。
问题已解决。我们发现 docker 中的 JVM 获得了错误的 CPU 核心编号。来自裸机而非 docker 配置的数字。我添加了 -XX:ParallelGCThreads=6 来控制 parNew gc 线程数。 GC时间减少到50ms，稳定了。
问题描述
我们的 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日志和安全点日志，怀疑是安全点导致的。但是我发现旋转时间+阻塞时间非常短。只有在young gc发生的时候，vmop的时间和young gc停止的时间差不多。
然后我检查 FinalRefence 集合，并添加 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
从年轻代回收后的剩余堆占用率可以看出，您的应用程序的活动集大小（包括新旧对象）似乎小于 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 热节流也可能是一个问题，但这在服务器环境中不太常见。
问题已解决。我们发现 docker 中的 JVM 获得了错误的 CPU 核心编号。来自裸机而非 docker 配置的数字。我添加了 -XX:ParallelGCThreads=6 来控制 parNew gc 线程数。 GC时间减少到50ms，稳定了。