GC 似乎导致 java 服务器应用程序无响应答案

【问题标题】：GC seems to cause unresponsiveness in java server appGC 似乎导致 java 服务器应用程序无响应
【发布时间】：2010-10-01 13:20:20
【问题描述】：

我们在 12 核 IBM 机器上的 RedHat Linux 5.2 上创建了一个在 JBoss 4.2.3 中运行的 webapp。最近我们看到响应时间很长，这似乎是由 GC 活动引起的。模式或多或少如下：所有请求似乎都以正常速率出现，但直到突然所有响应都“刷新”后才发送字节。同时 gc.log 有这个模式：

// 这里开始无响应 36788.309: [GC [1 CMS-initial-mark: 1919297K(4456448K)] 1969797K(5111808K), 0.1473460 secs] [Times: user=0.15 sys=0.00, real=0.15 secs] 应用程序线程停止的总时间：0.1530790 秒 36788.457：[CMS 并发标记开始] 36793.886：[CMS 并发标记：5.429/5.429 秒]（CMS 并发标记产生 46 次） [时间：用户=6.69 系统=0.07，真实=5.43 秒] 36793.886：[CMS-并发-预清洁-启动] （cardTable：15956张卡片，重新扫描15956张卡片，1次迭代） 36793.988：[CMS-concurrent-preclean：0.089/0.101 秒]（CMS-concurrent-preclean 产生 9 次） [时间：用户=0.12 系统=0.01，真实=0.10 秒] 36793.988：[CMS 并发中止预清理启动] （cardTable：75张卡片，重新扫描75张卡片，1次迭代）申请时间：5.6923460秒应用程序线程停止的总时间：0.0170000 秒（cardTable：96张卡片，重新扫描96张卡片，1次迭代）（cardTable：207张卡片，重新扫描207张卡片，1次迭代）（cardTable：45张卡片，重新扫描45张卡片，1次迭代）（cardTable：157张卡片，重新扫描157张卡片，1次迭代）（cardTable：88张卡片，重新扫描88张卡片，1次迭代）（cardTable：213张卡片，重新扫描213张卡片，1次迭代）（cardTable：84张卡片，重新扫描84张卡片，1次迭代）（cardTable：143张卡片，重新扫描143张卡片，1次迭代）（cardTable：40张卡片，重新扫描40张卡片，1次迭代）（cardTable：109张卡片，重新扫描109张卡片，1次迭代）（cardTable：77张卡片，重新扫描77张卡片，1次迭代）（cardTable：156张卡片，重新扫描156张卡片，1次迭代）（cardTable：132张卡片，重新扫描132张卡片，1次迭代）（cardTable：119张卡片，重新扫描119张卡片，1次迭代）（cardTable：115张卡片，重新扫描115张卡片，1次迭代）（cardTable：195张卡片，重新扫描195张卡片，1次迭代）（cardTable：163张卡片，重新扫描163张卡片，1次迭代）（cardTable：166张卡片，重新扫描166张卡片，1次迭代）（cardTable：149张卡片，重新扫描149张卡片，1次迭代）（cardTable：218张卡片，重新扫描218张卡片，1次迭代）（cardTable：46张卡片，重新扫描46张卡片，1次迭代）（cardTable：57张卡片，重新扫描57张卡片，1次迭代）（cardTable：213张卡片，重新扫描213张卡片，1次迭代）（cardTable：189张卡片，重新扫描189张卡片，1次迭代）（cardTable：104张卡片，重新扫描104张卡片，1次迭代）（cardTable：60张卡片，重新扫描60张卡片，1次迭代）（cardTable：368张卡片，重新扫描368张卡片，1次迭代）（cardTable：118张卡片，重新扫描118张卡片，1次迭代）（cardTable：129张卡片，重新扫描129张卡片，1次迭代）（cardTable：291张卡片，重新扫描291张卡片，1次迭代）（cardTable：105张卡片，重新扫描105张卡片，1次迭代）（cardTable：63张卡片，重新扫描63张卡片，1次迭代）（cardTable：73张卡片，重新扫描73张卡片，1次迭代）（cardTable：165张卡片，重新扫描165张卡片，1次迭代）（cardTable：69张卡片，重新扫描69张卡片，1次迭代）（cardTable：157张卡片，重新扫描157张卡片，1次迭代） CMS：由于时间原因中止预清理 [37 次迭代，13 次等待，4954 张卡）] 36799.161：[CMS-concurrent-abortable-preclean：2.965/5.173 秒]（CMS-concurrent-abortable-preclean 产生了 166 次） [时间：用户=5.12 系统=0.10，真实=5.17 秒] 申请时间：4.9945030秒 36799.172：[GC [YG 占用：572074 K (655360 K)]36799.172：[GC 36799.173：[ParNew 所需的幸存者大小 67108864 字节，新阈值 2（最大 15） - 年龄 1：59654872 字节，总共 59654872 - 年龄 2：26827232 字节，总共 86482104 - 年龄 3：2613360 字节，总共 89095464 - 年龄 4：929600 字节，总共 90025064 - 5 岁：893176 字节，总共 90918240 - 6 岁：795736 字节，总共 91713976 - 7 岁：809240 字节，总共 92523216 - 8 岁：936216 字节，总共 93459432 - 9 岁：971376 字节，总共 94430808 - 10 岁：624472 字节，总共 95055280 - 11 岁：883616 字节，总共 95938896 - 12 岁：817296 字节，总共 96756192 - 13 岁：977992 字节，总共 97734184 - 14 岁：733816 字节，总共 98468000 - 15 岁：654744 字节，总共 99122744 : 572074K->110988K(655360K), 0.1855140 secs] 2491372K->2031059K(5111808K) icms_dc=0 , 0.1866380 secs] [Times: user=0.72 sys=0.00, real=0.19 secs] 36799.359：[重新扫描（并行）（幸存者：12chunks）在第 3 个线程中完成年轻一代重新扫描工作：0.032 秒在第 2 个线程中完成年轻一代重新扫描工作：0.035 秒在第 0 个线程中完成年轻一代重新扫描工作：0.035 秒在第 1 个线程中完成年轻一代重新扫描工作：0.035 秒在第 1 个线程中完成剩余的根重新扫描工作：0.030 秒在第 3 个线程中完成剩余的根重新扫描工作：0.033 秒在第二个线程中完成剩余的根重新扫描工作：0.032 秒在第 0 个线程中完成剩余的根重新扫描工作：0.042 秒在第 2 个线程完成脏卡重新扫描工作：0.029 秒在第 3 个线程完成脏卡重新扫描工作：0.031 秒在第 0 个线程完成脏卡重新扫描工作：0.019 秒在第 1 个线程完成脏卡重新扫描工作：0.031 秒在第 3 个线程中完成的工作窃取：0.000 秒在第 0 个线程中完成的工作窃取：0.000 秒在第二个线程中完成的工作窃取：0.000 秒在第 1 个线程中完成的工作窃取：0.000 秒 , 0.0959640 secs]36799.455: [weak refs processing, 0.0121220 secs] [1 CMS-remark: 1920070K(4456448K)] 2031059K(5111808K), 0.2952350 secs] [Times: user=1.11 sys=0.000 应用程序线程停止的总时间：0.3066430 秒 36799.468：[CMS 并发扫描启动] 36805.824：[CMS 并发扫描：6.355/6.356 秒]（CMS 并发扫描产生 515 次） [时间：用户=8.76 系统=0.24，真实=6.35 秒] 36805.824：[CMS-并发-重置-启动] 36805.903：[CMS 并发重置：0.079/0.079 秒]（CMS 并发重置产生 0 次） [时间：用户=0.64 系统=0.01，真实=0.07 秒] 申请时间：6.5590510秒 // 关于这里服务器开始发送响应 36806.044：[GC 36806.045：[ParNew 所需的幸存者大小 67108864 字节，新阈值 2（最大 15） - 年龄 1：55456640 字节，总共 55456640 - 年龄 2：54278984 字节，总共 109735624 : 635276K->131072K(655360K), 0.3230430 secs] 2554507K->2089990K(5111808K) icms_dc=0 , 0.3242750 secs] [Times: user=1.02 sys=0.02, real=0.33 secs] 应用程序线程停止的总时间：0.3422430 秒申请时间：0.7628480秒

我们尝试了各种 GC 设置，但最终或多或少都是这样。我们当前的参数：

-Xms4096m -Xmx5120m -XX:MaxPermSize=384m -XX:+UseConcMarkSweepGC -XX:+ExplicitGCInvokesConcurrent -XX:+PrintClassHistogram -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCDetails -XX:ReservedCodeCacheSize=64m -XX:NewSize=768m -XX:SurvivorRatio=4 -XX:+CMSParallelRemarkEnabled -XX:+CMSScavengeBeforeRemark -XX:+CMSIncrementalMode -XX:+CMSIncrementalPacing -XX:CMSIncrementalDutyCycleMin=0 -XX:CMSIncrementalDutyCycle=10 -XX:+UseTLAB -XX:ParallelGCThreads=4 -XX:+UseParNewGC -XX:MaxGCPauseMillis=1000 -XX:GCTimeRatio=10 -XX:+CMSPermGenSweepingEnabled -XX:+PrintCMSInitiationStatistics -XX:PrintCMSStatistics=1 -XX:+PrintGCTaskTimeStamps -XX:+PrintGCTimeStamps -verbose:gc -XX:+TraceClassLoading -XX:+TraceClassUnloading -XX:+PrintTenuringDistribution

我们怎样才能避免反应迟钝？

【问题讨论】：

您在生产环境中使用 -verbose:gc 吗？当然，记录所有 GC 活动会增加无响应。
是的，我是。但是我读过的所有博客都说 GC 日志不会减慢系统速度。即使确实如此，我猜这种放缓会一直存在。
您是否运行了分析器以找出哪些对象正在充斥堆并有助于 GC 运行？
不，我们没有。我有点不愿意这样做，因为我不确定在生产机器上运行分析器的影响。

标签： java garbage-collection

【解决方案1】：

GC 日志包含如下行：

应用程序线程停止的总时间：...秒

除非我弄错了，否则它们加起来不到 1 秒。这不会与您的 web 应用程序长时间无响应相冲突。

我将建议原因可能是其他原因。一种可能性是您正在突破机器的限制，并且运行 GC 的额外负载导致请求积压。例如，由于您配置了 4 个并行 GC 线程，我预计理论最大请求率在 GC 运行时会下降 33%（16 秒？）。这可能会导致大量请求积压。

第二种可能是您的机器缺少物理内存，而 GC 将其推入了轻微的虚拟内存抖动情况。

【讨论】：

是的，无响应与“应用程序线程已停止...”语句无关。然而，这些问题确实与 CMS 语句有关。该请求似乎不仅仅减少了响应时间。
@Morten - 这往往支持我的替代解释，IMO。
@Morten - 我不明白你的意思 “请求似乎并没有减少响应时间。”？
对不起，我的意思是请求 rate。响应似乎挂起，然后突然响应被传递。
@Morten - 您是否实际测量过请求率和响应时间，或者这只是“感觉就像......”的观察？在后一种情况下，您真的应该在对可能发生的事情做出任何结论之前进行一些严格的测量。

【解决方案2】：

添加一个问题作为答案，因为我还没有代表添加 cmets。你在哪个 JRE 上运行？

【讨论】：

JDK 1.6.0_06。抱歉忘了提。
嗯，重新阅读您的问题，我看到您说的是“最近”，这是否意味着它直到最近才“正常”运行？负载/吞吐量/内存占用大致相同？
嗯，实际上它已经存在了一段时间。我们确实有一段没有问题的时期。
您是否能够随时间对服务器上的负载进行一些测量？这可能不是 GC 的错（实际上），尽管您可能需要根据应用程序更改的使用配置文件更改您的 GC 设置。如果您可以在 pre-PRD/UAT 中获得类似的设置，那么我可以推荐使用 JMeter 和一个分析工具来发现是什么触发了 GC 的行为和/或帮助发现真正的根本原因是什么。跨度>
我也非常讨厌将其添加为“建议”，但如果您真的很绝望，您可以尝试简单地将 JRE 更新到 1.6.0_21，自 _06 以来已经有一些 GC 修复和性能增强。但是，您显然最好在应用此类修复之前找到根本原因。