java - 为什么这个特定的次要 GC 这么慢

Question

我们有一个在 tomcat 6.0.35 和 JDK 7u60 上运行的 Jira 6.3.10 应用程序。操作系统为Centos 6.2，内核为2.6.32-220.7.1.el6.x86_64。 我们有时会注意到应用程序中的暂停。我们发现了与 GC 的相关性。

内存的启动选项是:-Xms16384m -Xmx16384m -XX:NewSize=6144m -XX:MaxPermSize=512m -XX:+UseCodeCacheFlushing -XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled -XX:ReservedCodeCacheSize=512m -XX:+DisableExplicitGC

问题是我无法解释为什么特定的 Minor GC 花费了将近 7 秒。请参阅集合:2015-09-17T14:59:42.485+0000。用户注意到有 1 分钟多一点的停顿。

从我在 http://blog.ragozin.info/2011/06/understanding-gc-pauses-in-jvm-hotspots.html 上可以读到的内容，我认为是 Tcard_scan 决定了这个缓慢的收集，但我不确定，我无法解释为什么会发生这种情况。

2015-09-17T14:57:03.824+0000: 3160725.220: [GC2015-09-17T14:57:03.824+0000: 3160725.220: [ParNew: 5112700K->77061K(5662336K), 0.0999740 secs] 10048034K->5017436K(16148096K), 0.1002730 secs] [Times: user=1.01 sys=0.02, real=0.10 secs]
2015-09-17T14:57:36.631+0000: 3160758.027: [GC2015-09-17T14:57:36.631+0000: 3160758.027: [ParNew: 5110277K->127181K(5662336K), 0.0841060 secs] 10050652K->5075489K(16148096K), 0.0843680 secs] [Times: user=0.87 sys=0.02, real=0.09 secs]
2015-09-17T14:57:59.494+0000: 3160780.890: [GC2015-09-17T14:57:59.494+0000: 3160780.890: [ParNew: 5160397K->104929K(5662336K), 0.1033160 secs] 10108705K->5056258K(16148096K), 0.1036150 secs] [Times: user=0.62 sys=0.00, real=0.11 secs]
2015-09-17T14:58:27.069+0000: 3160808.464: [GC2015-09-17T14:58:27.069+0000: 3160808.465: [ParNew: 5138145K->86797K(5662336K), 0.0844890 secs] 10089474K->5039063K(16148096K), 0.0847790 secs] [Times: user=0.68 sys=0.01, real=0.09 secs]
2015-09-17T14:58:43.489+0000: 3160824.885: [GC2015-09-17T14:58:43.489+0000: 3160824.885: [ParNew: 5120013K->91000K(5662336K), 0.0588270 secs] 10072279K->5045124K(16148096K), 0.0590680 secs] [Times: user=0.53 sys=0.01, real=0.06 secs]
2015-09-17T14:59:03.831+0000: 3160845.227: [GC2015-09-17T14:59:03.832+0000: 3160845.227: [ParNew: 5124216K->89921K(5662336K), 0.1018980 secs] 10078340K->5047918K(16148096K), 0.1021850 secs] [Times: user=0.56 sys=0.01, real=0.10 secs]
2015-09-17T14:59:42.485+0000: 3160883.880: [GC2015-09-17T14:59:42.485+0000: 3160883.880: [ParNew: 5123137K->98539K(5662336K), 6.9674580 secs] 10081134K->5061766K(16148096K), 6.9677100 secs] [Times: user=102.14 sys=0.05, real=6.97 secs]
2015-09-17T15:00:17.679+0000: 3160919.075: [GC2015-09-17T15:00:17.680+0000: 3160919.075: [ParNew: 5131755K->141258K(5662336K), 0.1189970 secs] 10094982K->5107030K(16148096K), 0.1194650 secs] [Times: user=0.80 sys=0.00, real=0.12 secs]
2015-09-17T15:01:20.149+0000: 3160981.545: [GC2015-09-17T15:01:20.149+0000: 3160981.545: [ParNew: 5174474K->118871K(5662336K), 0.1251710 secs] 10140246K->5089067K(16148096K), 0.1255370 secs] [Times: user=0.63 sys=0.00, real=0.12 secs]
2015-09-17T15:03:07.323+0000: 3161088.718: [GC2015-09-17T15:03:07.323+0000: 3161088.719: [ParNew: 5152087K->80387K(5662336K), 0.0782410 secs] 10122283K->5055601K(16148096K), 0.0785610 secs] [Times: user=0.57 sys=0.01, real=0.07 secs]
2015-09-17T15:03:26.396+0000: 3161107.791: [GC2015-09-17T15:03:26.396+0000: 3161107.791: [ParNew: 5113538K->66134K(5662336K), 0.0697170 secs] 10088753K->5044322K(16148096K), 0.0699990 secs] [Times: user=0.48 sys=0.01, real=0.07 secs]
2015-09-17T15:03:47.185+0000: 3161128.580: [GC2015-09-17T15:03:47.185+0000: 3161128.581: [ParNew: 5099350K->62874K(5662336K), 0.0692700 secs] 10077538K->5043879K(16148096K), 0.0695140 secs] [Times: user=0.61 sys=0.02, real=0.07 secs]
2015-09-17T15:04:04.503+0000: 3161145.899: [GC2015-09-17T15:04:04.503+0000: 3161145.899: [ParNew: 5096090K->63684K(5662336K), 0.0709490 secs] 10077095K->5047678K(16148096K), 0.0712390 secs] [Times: user=0.54 sys=0.01, real=0.07 secs]
2015-09-17T15:04:48.013+0000: 3161189.409: [GC2015-09-17T15:04:48.013+0000: 3161189.409: [ParNew: 5096900K->74854K(5662336K), 0.1530160 secs] 10080894K->5061766K(16148096K), 0.1533520 secs] [Times: user=0.76 sys=0.00, real=0.15 secs] 

我们有 198GB 内存。服务器未主动交换。这个特定的 Jira 实例具有相当高的使用率。有一些自动化工具一直在戳这个实例。 服务器上的内存状态:

$ cat /proc/meminfo
MemTotal:       198333224 kB
MemFree:        13194296 kB
Buffers:           93948 kB
Cached:         10236288 kB
SwapCached:      1722248 kB
Active:         168906584 kB
Inactive:       10675040 kB
Active(anon):   163755088 kB
Inactive(anon):  5508552 kB
Active(file):    5151496 kB
Inactive(file):  5166488 kB
Unevictable:        4960 kB
Mlocked:            4960 kB
SwapTotal:       6193136 kB
SwapFree:             12 kB
Dirty:             14040 kB
Writeback:             0 kB
AnonPages:      167534556 kB
Mapped:          1341076 kB
Shmem:              9196 kB
Slab:            2117816 kB
SReclaimable:    1258104 kB
SUnreclaim:       859712 kB
KernelStack:       51048 kB
PageTables:       431780 kB
NFS_Unstable:          0 kB
Bounce:                0 kB
WritebackTmp:          0 kB
CommitLimit:    105359748 kB
Committed_AS:   187566824 kB
VmallocTotal:   34359738367 kB
VmallocUsed:      680016 kB
VmallocChunk:   34255555544 kB
HardwareCorrupted:     0 kB
AnonHugePages:  79947776 kB
HugePages_Total:       0
HugePages_Free:        0
HugePages_Rsvd:        0
HugePages_Surp:        0
Hugepagesize:       2048 kB
DirectMap4k:        5604 kB
DirectMap2M:     2078720 kB
DirectMap1G:    199229440 kB

在同一台机器上运行的其他 Jira 实例不受影响。我们在这台机器上运行 30 个 Jira 实例。

Answer 1

一般情况

这可能是另一个占用资源的进程(或交换增加的开销):

Sometimes the OS activities such as the swap space or networking activity happening at the time when GC is taking place can make the GC pauses last much longer. These pauses can be of the order of few seconds to some minutes.

If your system is configured to use swap space, Operating System may move inactive pages of memory of the JVM process to the swap space, to free up memory for the currently active process which may be the same process or a different process on the system. Swapping is very expensive as it requires disk accesses which are much slower as compared to the physical memory access. So, if during a garbage collection the system needs to perform swapping, the GC would seem to run for a very long time.

来源:https://blogs.oracle.com/poonam/entry/troubleshooting_long_gc_pauses

本文还提供了一些您可能感兴趣的一般指示。

---

特别是

但是，在这种情况下，我认为问题更有可能是您的服务器上运行的 JVM 数量。

30 * 不同的堆，加上 JVM 开销可能会导致大量内存使用。如果总堆分配超过物理内存的 75%，您可能会遇到上述问题(交换 Activity 会揭示这一点)。

更重要的是，线程 CPU 争用很可能是这里的真正 killer 。根据经验，我的 JVM 数量不会超过逻辑 CPU 的数量(如果要同时使用这些实例)。

此外，我尽量确保 GC 线程数不超过可用虚拟 CPU 内核数的 4 倍。

在 30 * 18(根据您的评论)，这可能是 540 个 GC 线程。我假设您的系统没有 135 个逻辑内核？

如果我对响应速度的要求较低，我可能会采用 8 比 1 的比例。但这只是我在单个系统上的范围 - 独立的 JVM 相互竞争资源。

---

建议

减少 ParallelGCThreads 的数量，目的是使总数低于 4 倍阈值。我知道这不切实际，将低优先级 JVM 设置为低值 (2) 并适本地设置高优先级 JVM(可能为 4 或 8)？

此外，我不确定设置 ConcGCThreads = 0 的含义，因为我假设您不能没有任何工作线程的 CMS...？如果未设置该值，则行为是 JVM 根据系统自行决定。我希望这也是 0 设置的行为——这在共享系统上可能是一个太高的值。尝试明确设置它。