为什么这个特殊的次要 GC 这么慢

【问题标题】：Why this particular minor GC was so slow为什么这个特殊的次要 GC 这么慢
【发布时间】：2015-09-18 12:54:33
【问题描述】：

我们有一个在 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 实例。

【问题讨论】：

  • 服务器有多少物理内存可用？是否有其他应用程序或繁重的进程正在运行？
  • 我们有 189 GB 的物理内存。 12GB 可用空间和 9GB 文件系统缓存。应用程序使用了 166GB。
  • 所有 30 个 Jira 实例是否都在自己的 JVM 中运行，配置了 16 GiB 堆？还有，配置了多少个GC线程？
  • 对于堆，它们中的大多数都在 2-4 GB 的范围内。我们正在使用默认值，它们是：ConcGCThreads = 0 和 ParallelGCThreads = 18，由 /usr/java/jdk1.7/bin/java -XX:+UnlockDiagnosticVMOptions -XX:+UnlockExperimentalVMOptions -XX:+PrintFlagsFinal -version|grep -i gcthreads 报告
  • ConcGCThreads 在启用 CMS 时默认为 5。至少这是这样报告的：java -XX:+UnlockDiagnosticVMOptions -XX:+UnlockExperimentalVMOptions -XX:+PrintFlagsFinal -XX:+UseConcMarkSweepGC -version 2>/dev/null|grep ConcGCThreads

标签： java garbage-collection jvm


【解决方案1】：

一般情况

这可能是另一个进程占用资源（或交换增加的开销）：

有时是操作系统活动，例如交换空间或网络 GC 发生时发生的活动可以使 GC 停顿时间更长。这些停顿可以是几个 几秒钟到几分钟。

如果您的系统配置为使用交换空间，操作系统可能 将 JVM 进程的非活动内存页移动到交换空间，以 为可能相同的当前活动进程释放内存 进程或系统上的不同进程。换货很 昂贵，因为它需要磁盘访问速度要慢得多 与物理内存访问相比。所以，如果在垃圾期间 收集系统需要执行交换，GC 似乎 运行很长时间。

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

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

具体

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

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

更重要的是，线程 CPU 争用很可能是这里的真正杀手。根据经验，我的 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 设置的行为——这在共享系统上可能是一个太高的值。尝试明确设置。

【讨论】：

  • 非常好，但事实并非如此。请参阅我编辑的问题。
  • 确实，有些实例开始被更多使用而你同时运行GC时，有时会出现问题。但是，当只有一个实例存在性能问题时，这个特定问题就不是这样了。我的感觉是它不是由系统问题引起的，而是由特定的使用模式引起的。让我不解的是，minor collection time 似乎并没有比其他minor GC 前后有什么特别之处。
  • 一些实例处于空闲状态，只有内部调度程序和监控在其中运行一些东西。由于大多数对象没有被触及，由于最近内核中的预期分页机制，它们的一些页面被复制到页面文件中。见：en.wikipedia.org/wiki/Paging#Anticipatory_paging
  • 为小型实例设置较低的ParallelGCThreads 是个好主意。谢谢！我不认为它会解决这个特定问题，但肯定会有助于优化环境。
  • 请注意：ConcGCThreads 在使用 CMS 时默认为 5。
猜你喜欢
  • 1970-01-01
  • 2012-07-27
  • 1970-01-01
  • 1970-01-01
  • 2011-03-11
  • 1970-01-01
  • 1970-01-01
  • 1970-01-01
  • 2012-08-31
相关资源
最近更新 更多
热门标签
Java Python linux javascript Mysql C# Docker 算法 前端 SpringBoot Redis Vue spring 设计模式 .net core .net kubernetes c++ 数据库 数据结构 大数据 js 机器学习 微服务 Android Go 程序员 面试 JVM ASP.net core 云原生 人工智能 后端 PHP git CSS golang k8s Nginx Django mybatis 深度学习 多线程 React 架构 devops 爬虫 云计算 Spring Boot LeetCode