Cassandra修复失败,因为GC问题。

3
我们有一个由9个节点组成的集群,并按建议每晚运行修复程序(每晚1个节点)。
最近我们在进行修复时出现了问题,因为一些节点由于GC无法快速回收而死亡。起初是晋升问题(详细的GC日志显示),所以我们认为CMS触发得不够快,导致ParNew无法晋升幸存对象。于是我们将XX:CMSInitiatingOccupancyFraction从75降低到50,以强制老年代GC更快地触发。
看起来效果不错,但昨天有两个节点因分配速度过快而GC难以应对而死亡,产生了这种日志:
INFO [ScheduledTasks:1] 2013-09-27 23:36:38,111 GCInspector.java (line 119) GC for ConcurrentMarkSweep: 21756 ms for 1 collections, 8003258240 used; max is 8211660800
WARN [ScheduledTasks:1] 2013-09-27 23:36:38,878 GCInspector.java (line 142) Heap is 0.9746211436302873 full.  You may need to reduce memtable and/or cache sizes.  Cassandra will now flush up to the two largest memtables to free up memory.  Adjust flush_largest_memtables_at threshold in cassandra.yaml if you don't want Cassandra to do this automatically
INFO [ScheduledTasks:1] 2013-09-27 23:36:57,018 GCInspector.java (line 119) GC for ConcurrentMarkSweep: 17265 ms for 1 collections, 6587223560 used; max is 8211660800
WARN [ScheduledTasks:1] 2013-09-27 23:36:57,243 GCInspector.java (line 142) Heap is 0.802179208376459 full.  You may need to reduce memtable and/or cache sizes.  Cassandra will now flush up to the two largest memtables to free up memory.  Adjust flush_largest_memtables_at threshold in cassandra.yaml if you don't want Cassandra to do this automatically
INFO [ScheduledTasks:1] 2013-09-27 23:37:18,180 GCInspector.java (line 119) GC for ConcurrentMarkSweep: 18437 ms for 1 collections, 6961687392 used; max is 8211660800
WARN [ScheduledTasks:1] 2013-09-27 23:37:18,785 GCInspector.java (line 142) Heap is 0.8477806818323523 full.  You may need to reduce memtable and/or cache sizes.  Cassandra will now flush up to the two largest memtables to free up memory.  Adjust flush_largest_memtables_at threshold in cassandra.yaml if you don't want Cassandra to do this automatically
INFO [ScheduledTasks:1] 2013-09-27 23:37:40,416 GCInspector.java (line 119) GC for ConcurrentMarkSweep: 19032 ms for 1 collections, 7338693168 used; max is 8211660800
WARN [ScheduledTasks:1] 2013-09-27 23:37:40,456 GCInspector.java (line 142) Heap is 0.893691708259552 full.  You may need to reduce memtable and/or cache sizes.  Cassandra will now flush up to the two largest memtables to free up memory.  Adjust flush_largest_memtables_at threshold in cassandra.yaml if you don't want Cassandra to do this automatically
INFO [ScheduledTasks:1] 2013-09-27 23:38:02,994 GCInspector.java (line 119) GC for ConcurrentMarkSweep: 18853 ms for 1 collections, 7570047632 used; max is 8211660800
WARN [ScheduledTasks:1] 2013-09-27 23:38:03,008 GCInspector.java (line 142) Heap is 0.9218656026318086 full.  You may need to reduce memtable and/or cache sizes.  Cassandra will now flush up to the two largest memtables to free up memory.  Adjust flush_largest_memtables_at threshold in cassandra.yaml if you don't want Cassandra to do this automatically
INFO [ScheduledTasks:1] 2013-09-27 23:38:26,110 GCInspector.java (line 119) GC for ConcurrentMarkSweep: 19564 ms for 1 collections, 7714594464 used; max is 8211660800
WARN [ScheduledTasks:1] 2013-09-27 23:38:26,132 GCInspector.java (line 142) Heap is 0.9394682332713986 full.  You may need to reduce memtable and/or cache sizes.  Cassandra will now flush up to the two largest memtables to free up memory.  Adjust flush_largest_memtables_at threshold in cassandra.yaml if you don't want Cassandra to do this automatically
INFO [ScheduledTasks:1] 2013-09-27 23:38:49,733 GCInspector.java (line 119) GC for ConcurrentMarkSweep: 20388 ms for 1 collections, 7843428464 used; max is 8211660800
WARN [ScheduledTasks:1] 2013-09-27 23:38:49,748 GCInspector.java (line 142) Heap is 0.9551573859456055 full.  You may need to reduce memtable and/or cache sizes.  Cassandra will now flush up to the two largest memtables to free up memory.  Adjust flush_largest_memtables_at threshold in cassandra.yaml if you don't want Cassandra to do this automatically
INFO [ScheduledTasks:1] 2013-09-27 23:39:14,564 GCInspector.java (line 119) GC for ConcurrentMarkSweep: 20956 ms for 1 collections, 7934286376 used; max is 8211660800
WARN [ScheduledTasks:1] 2013-09-27 23:39:14,578 GCInspector.java (line 142) Heap is 0.9662218848591505 full.  You may need to reduce memtable and/or cache sizes.  Cassandra will now flush up to the two largest memtables to free up memory.  Adjust flush_largest_memtables_at threshold in cassandra.yaml if you don't want Cassandra to do this automatically
INFO [ScheduledTasks:1] 2013-09-27 23:39:40,186 GCInspector.java (line 119) GC for ConcurrentMarkSweep: 22440 ms for 1 collections, 8008275464 used; max is 8211660800
WARN [ScheduledTasks:1] 2013-09-27 23:39:40,915 GCInspector.java (line 142) Heap is 0.9752321313612954 full.  You may need to reduce memtable and/or cache sizes.  Cassandra will now flush up to the two largest memtables to free up memory.  Adjust flush_largest_memtables_at threshold in cassandra.yaml if you don't want Cassandra to do this automatically
INFO [ScheduledTasks:1] 2013-09-27 23:40:01,836 GCInspector.java (line 119) GC for ConcurrentMarkSweep: 19911 ms for 1 collections, 8022614576 used; max is 8211660800
WARN [ScheduledTasks:1] 2013-09-27 23:40:06,032 GCInspector.java (line 142) Heap is 0.976978320390438 full.  You may need to reduce memtable and/or cache sizes.  Cassandra will now flush up to the two largest memtables to free up memory.  Adjust flush_largest_memtables_at threshold in cassandra.yaml if you don't want Cassandra to do this automatically
INFO [ScheduledTasks:1] 2013-09-27 23:40:27,407 GCInspector.java (line 119) GC for ConcurrentMarkSweep: 22590 ms for 1 collections, 8058828880 used; max is 8211660800
WARN [ScheduledTasks:1] 2013-09-27 23:40:31,091 GCInspector.java (line 142) Heap is 0.9813884275395302 full.  You may need to reduce memtable and/or cache sizes.  Cassandra will now flush up to the two largest memtables to free up memory.  Adjust flush_largest_memtables_at threshold in cassandra.yaml if you don't want Cassandra to do this automatically
INFO [GossipTasks:1] 2013-09-27 23:40:53,798 Gossiper.java (line 799) InetAddress /<datacenter02>.<node2> is now DOWN
INFO [GossipTasks:1] 2013-09-27 23:40:53,846 Gossiper.java (line 799) InetAddress /<datacenter01>.<node3> is now DOWN
INFO [GossipStage:1] 2013-09-27 23:40:53,857 Gossiper.java (line 785) InetAddress /<datacenter01>.<node3> is now UP
INFO [GossipStage:1] 2013-09-27 23:40:53,909 Gossiper.java (line 785) InetAddress /<datacenter02>.<node2> is now UP

这次堆增长并且GC运行了10到20秒,但没有减小堆大小,导致节点认为彼此失效,因为它们正在忙于进行垃圾回收。最终,节点因OOM而死亡。
然后我们尝试升级到最新版本的Cassandra(1.2.8 -> 1.2.10),尽管这些版本中没有修复我们问题的固定bug。昨晚我们进行了一次修复,但即使没有节点崩溃,由于出现了这种GC,它们无法修复某些范围。
INFO [ScheduledTasks:1] 2013-09-29 04:45:05,467 GCInspector.java (line 119) GC for ParNew: 22875 ms for 2 collections, 4128819328 used; max is 8211660800
INFO [ScheduledTasks:1] 2013-09-29 04:53:24,597 GCInspector.java (line 119) GC for ParNew: 133643 ms for 2 collections, 3102634584 used; max is 8211660800

这次是ParNew花费了荒谬的时间。

我最初认为是负载问题,但在周末只进行修复时仍然出现了这种情况。

求助于任何能够诊断/解决我们问题的人。


查看堆转储以查看内存去向:http://www.eclipse.org/mat/ - jbellis
另外,当StatusLogger开始出问题时,它在说些什么? - jbellis
关于堆转储,不幸的是它们无法适应驱动器并且无法完全转储。关于日志,这里有一个Pastebin链接,其中包含在长时间GC之一发生的StatusLogger http://pastebin.com/gkcCnXGy - alprema
@jbellis 我应该在Cassandra的JIRA上报告一个bug,还是你认为这更多是配置问题? - alprema
2个回答

2

状态日志信息没有显示任何异常,除了垃圾回收需要一段时间。(您是在虚拟机上运行吗?这往往会降低GC性能:http://www.slideshare.net/eonnen/high-performance-network-programming-on-the-jvm-oscon-2012/62。)

我的猜测:修复操作会给系统增加足够的负载,导致它在处理请求时落后,并花费过多的内存缓冲它们。您可以通过查看日志中的“已丢弃”消息来验证这一点。默认情况下,它将缓冲10秒的请求;为了减少这个时间,请在cassandra.yaml中降低适当的rpc超时。


我们不是在虚拟机上运行。关于缓冲区的想法,我并不认同,因为即使在周末几乎没有活动时,这种情况仍然会发生。 无论如何,在JVM更新后的第一次修复仍然很长,但之后一切都恢复正常了。 我并不确定更新解决了我们的问题,现在我会考虑它已经关闭,但会继续关注服务器。 感谢您的帮助。 - alprema

0

网页内容由stack overflow 提供, 点击上面的
可以查看英文原文,
原文链接