java - 为什么只有用户时间非常长的长 ParNew GC？

Question

我在容器中运行一个 Java 应用程序(使用 k8s)，发现一个长的 STW gc:

2019-07-10T16:45:31.081+0800: 1620992.943: [GC (Allocation Failure) 2019-07-10T16:45:31.082+0800: 1620992.944: [ParNew: 1232340K->105476K(1258304K), 0.0558525 secs] 1412255K->290236K(4054528K), 0.0571538 secs] [Times: user=0.23 sys=0.20, real=0.06 secs] 
2019-07-10T16:46:08.906+0800: 1621030.767: [GC (Allocation Failure) 2019-07-10T16:46:08.907+0800: 1621030.768: [ParNew: 1224004K->97149K(1258304K), 5.4008859 secs] 1408764K->286575K(4054528K), 5.4022113 secs] [Times: user=37.65 sys=0.00, real=5.41 secs] 
2019-07-10T16:46:48.426+0800: 1621070.287: [GC (Allocation Failure) 2019-07-10T16:46:48.426+0800: 1621070.288: [ParNew: 1215677K->106022K(1258304K), 0.0545431 secs] 1405103K->300294K(4054528K), 0.0557196 secs] [Times: user=0.41 sys=0.00, real=0.06 secs]

与之前和下一次 GC 相比，第二次 GC 回收了几乎相同数量的内存 (1.1GB)，同时花费了大量时间(5.4 秒)。这与 ParNew GC 中非常高的用户时间有关。

我用 Google 搜索了一下，发现大多数博客和 stackoverflow 答案都在处理大型系统时间和实时，这与我的问题无关。

我的 Java 版本:

$ java -version
java version "1.8.0_102"
Java(TM) SE Runtime Environment (build 1.8.0_102-b14)
Java HotSpot(TM) 64-Bit Server VM (build 25.102-b14, mixed mode)

来自 jstack 的 GC 线程是:

"Concurrent Mark-Sweep GC Thread" os_prio=0 tid=0x00007f3be809b000 nid=0xb5 runnable 
"Gang worker#0 (Parallel GC Threads)" os_prio=0 tid=0x00007f3be801d000 nid=0xab runnable 
"Gang worker#1 (Parallel GC Threads)" os_prio=0 tid=0x00007f3be801f000 nid=0xac runnable 
"Gang worker#2 (Parallel GC Threads)" os_prio=0 tid=0x00007f3be8020800 nid=0xad runnable 
"Gang worker#3 (Parallel GC Threads)" os_prio=0 tid=0x00007f3be8022800 nid=0xae runnable 
"Gang worker#4 (Parallel GC Threads)" os_prio=0 tid=0x00007f3be8024800 nid=0xaf runnable 
"Gang worker#5 (Parallel GC Threads)" os_prio=0 tid=0x00007f3be8026000 nid=0xb0 runnable 
"Gang worker#6 (Parallel GC Threads)" os_prio=0 tid=0x00007f3be8028000 nid=0xb1 runnable 
"Gang worker#7 (Parallel GC Threads)" os_prio=0 tid=0x00007f3be802a000 nid=0xb2 runnable 
"Surrogate Locker Thread (Concurrent GC)" #4 daemon prio=9 os_prio=0 tid=0x00007f3be812d800 nid=0xb9 waiting on condition [0x0000000000000000]
"Gang worker#0 (Parallel CMS Threads)" os_prio=0 tid=0x00007f3be8097000 nid=0xb3 runnable 
"Gang worker#1 (Parallel CMS Threads)" os_prio=0 tid=0x00007f3be8099000 nid=0xb4 runnable 

Answer 1

实时时间是挂钟时间，即实际过去了多少时间。用户时间是在用户空间中花费的所有内核上聚合的 CPU 周期，用于工作。由于您有 8 个并行 GC 线程，这意味着这 5 秒中的大部分时间都花在了大多数执行收集工作的核心上。

这本身并没有告诉我们为什么要花那么多时间。据我所知，要从 ParNew 中获取更多信息，可以做的事情并不多，它是一个非常简单的收集器。您可以切换到提供更详细日志的 G1。

Understanding GC pauses in JVM, HotSpot's minor GC Alexey Ragozin 对 ParNew 时间花费进行了分割。

您可能还想监控您的系统是否存在 CPU/IO/Swap 争用(例如，通过在当前 Linux 内核中使用时间戳记录/proc/pressure/* 可能有用)，这可能会减慢垃圾收集器的 Activity 。