具有极值实时值的 Java GC 日志

Question

我有以下 GC 日志，其中显示的时间不太正确:

2017-10-01T11:42:19.115+0200: 158277.307: [GC (Allocation Failure) 2017-10-01T11:42:19.115+0200: 158277.307: [ParNew: 83271K->1819K(92160K), 0.0267320 secs] 285034K->203588K(296960K) icms_dc=0 , 0.0269819 secs] [Times: user=0.09 sys=0.00, real=0.03 secs] 
2017-10-01T11:42:34.459+0200: 158292.637: [GC (Allocation Failure) 2017-10-01T11:42:34.459+0200: 158292.637: [ParNew: 83739K->1778K(92160K), 0.0046469 secs] 285508K->203547K(296960K) icms_dc=0 , 0.0049024 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2017-10-01T11:42:45.053+0200: 158303.240: [GC (Allocation Failure) 2017-10-01T11:42:45.053+0200: 158303.240: [ParNew: 83698K->1475K(92160K), 0.0257372 secs] 285467K->204066K(296960K) icms_dc=12 , 0.0259963 secs] [Times: user=0.03 sys=0.00, real=0.03 secs] 
2017-10-01T11:42:51.273+0200: 158309.457: [CMS-concurrent-mark: 1.279/52268.162 secs] [Times: user=4273.98 sys=2016.78, real=52269.51 secs] 
2017-10-01T11:42:51.288+0200: 158309.466: [CMS-concurrent-preclean-start]
2017-10-01T11:42:51.288+0200: 158309.471: [CMS-concurrent-preclean: 0.006/0.006 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2017-10-01T11:42:51.288+0200: 158309.472: [CMS-concurrent-abortable-preclean-start]
2017-10-01T11:42:58.819+0200: 158317.005: [GC (Allocation Failure) 2017-10-01T11:42:58.819+0200: 158317.005: [ParNew: 83395K->978K(92160K), 0.0035692 secs] 285986K->203570K(296960K) icms_dc=12 , 0.0037514 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
 CMS: abort preclean due to time 2017-10-01T11:43:05.116+0200: 158323.306: [CMS-concurrent-abortable-preclean: 0.359/13.834 secs] [Times: user=1.45 sys=0.61, real=13.83 secs] 

特别注意第四行中的时间[Times: user=4273.98 sys=2016.78, real=52269.51 secs]。这将表明 GC 暂停约 14 小时!？!该系统在启用了 NTP 计时的 ESXI 虚拟化 Windows 上运行 Java 8。

编辑1:我或多或少在办公室的笔记本电脑上重现了这个问题。在裸硬件上运行 Windows 10，Oracle JDK 1.8u121 以下 8.7 和 37.9 秒的实时时间对我来说无法真正解释:

Java HotSpot(TM) 64-Bit Server VM (25.121-b13) for windows-amd64 JRE (1.8.0_121-b13), built on Dec 12 2016 18:21:36 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 8312128k(5673796k free), swap 9622848k(6661268k free)
CommandLine flags: -XX:+CMSIncrementalMode -XX:CompileThreshold=1500 -XX:+ExplicitGCInvokesConcurrent -XX:+HeapDumpOnOutOfMemoryError -XX:InitialHeapSize=268435456 -XX:MaxHeapSize=2127904768 -XX:MaxMetaspaceSize=268435456 -XX:MaxNewSize=348966912 -XX:MaxTenuringThreshold=6 -XX:OldPLABSize=16 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+TieredCompilation -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:-UseLargePagesIndividualAllocation -XX:+UseParNewGC 
2017-10-04T12:43:25.289+0200: 9.804: [CMS-concurrent-mark-start]
2017-10-04T12:43:33.995+0200: 18.501: [CMS-concurrent-mark: 0.033/8.698 secs] [Times: user=0.80 sys=0.08, real=8.71 secs] 
2017-10-04T12:43:33.995+0200: 18.501: [CMS-concurrent-preclean-start]
2017-10-04T12:43:33.995+0200: 18.503: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2017-10-04T12:43:33.995+0200: 18.503: [CMS-concurrent-abortable-preclean-start]
2017-10-04T12:43:57.870+0200: 42.375: [GC (Allocation Failure) 2017-10-04T12:43:57.870+0200: 42.375: [ParNew: 78655K->5667K(78656K), 0.0123267 secs] 117528K->48405K(253440K) icms_dc=5 , 0.0124366 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
 CMS: abort preclean due to time 2017-10-04T12:44:11.909+0200: 56.413: [CMS-concurrent-abortable-preclean: 0.398/37.910 secs] [Times: user=0.86 sys=0.09, real=37.91 secs] 

系统使用了大约 25% 的 CPU，以及 8GB 中的 ~3.5GB RAM。我 read up 如何读取这些 GC 日志文件和 CMS-concurrent-mark-start 到 CMS-concurrent-mark 似乎是已停止的线程重新启动的时间。此时我们在应用程序中运行大约 1000 个线程。重新启动线程是否计入实时而不是用户/系统？

编辑2:在同一台笔记本电脑上，我完全禁用了页面文件，但仍然获得了很高的实际值。

2017-10-04T17:12:47.593+0200: 21.755: [CMS-concurrent-mark: 0.036/5.195 secs] [Times: user=1.73 sys=0.09, real=5.20 secs] 

还运行了 perfmon 并观察了“页面错误/秒”、“页面输出/秒”，根据 Technet ，这应该为我提供有关硬页面错误的信息，这些错误是从磁盘加载数据的错误。 “页面输出/秒”为 0，因此没有硬分页。还有什么问题吗!线程仍然是一个嫌疑......

Answer 1

CommandLine flags: -XX:+CMSIncrementalMode [...]

您正在使用增量模式。 Don't do that ，就是deprecated并且只适用于单核 CPU，使用它没有意义。增量模式放弃了从收集器到应用程序线程的时间片，从而使得并发收集阶段比非增量模式花费更多的wall time(但不一定是CPU时间)。