背景说明
公司项目现有Cassandra集群在升级微服务的过程中,Cassandra涉及物化视图的创建,生同一个云内所有节点不停的Down,简单通过cqlsh工具连接,表现是集群时断时连
环境介绍
Cassandra集群一共12个节点,分别部署在两个云上,每个云上6个节点
| 云 | IP地址 | 硬件资源 |
| 云A | 1 | 32C64G |
| 云A | 2 | 32C64G |
| 云A | 3 | 32C64G |
| 云A | 4 | 32C64G |
| 云A | 5 | 32C64G |
| 云A | 6 | 32C64G |
| 云B | 7 | 32C64G |
| 云B | 8 | 32C64G |
| 云B | 9 | 32C64G |
| 云B | 10 | 32C64G |
| 云B | 11 | 32C64G |
| 云B | 12 | 32C64G |
排查过程
由于升级导致问题出现,着重排查Cassandra的修改内容,这里只做了物化视图的创建,重点进行Cassandra日志的排查,看看能否发现蛛丝马迹
WARN [CompactionExecutor:134534] 2021-12-21 06:18:07,400 ReadCommand.java:569 - Read 0 live rows and 1339 tombstone cells for query SELECt * FROM platform_log.systemloginfo WHERe stationid, subsystemid, equipmentid, timeframe = 2, 16, 3753, 20211119 (see tombstone_warn_threshold) WARN [CompactionExecutor:356] 2021-12-21 06:43:33,416 ViewBuilder.java:192 - Materialized View failed to complete, sleeping 5 minutes before restarting org.apache.cassandra.db.filter.TombstoneOverwhelmingException: Scanned over 100001 tombstones during query 'SELECt * FROM platform_log.systemloginfo WHERe stationid, subsystemid, equipmentid, timeframe = 0, 0, 7940, 20211221' (last scanned row partion key was ((0, 0, 7940, 20211221), 2021-12-22 21:36+0800, 3cb9e6f7-713b-4771-8cb9-a5265357c161, 0)); query aborted
通过解读上面日志可以看出,存在两方面的问题
tmbstone 墓碑数据,创建物化视图时,查询到了大量墓碑数据Full GC 老年代垃圾回收造成STW,时间长达90秒
针对两个问题分别进行优化处理
墓碑数据执行/usr/local/cassandra/bin/nodetool tablestats xxx 检查墓碑情况,下图为正常墓碑
cqlsh命令行查看物化视图创建进程
SELECt * FROM system.views_builds_in_progress;
调整基础的墓碑时效(注意物化视图也需要调整)
ALTER TABLE xxx WITH gc_grace_seconds = 300;
ALTER MATERIALIZED VIEW xxxx WITH gc_grace_seconds = 300;
清理节点上的墓碑数据(逐个节点进行清理)
/usr/local/cassandra/bin/nodetool garbagecollect xxxx;
2、JVM Full GC
修改/usr/local/cassandra/conf/jvm.options
输出日志到指定目录
-Xloggc:/var/lib/cassandra/gc.log
新增
//如今,被广泛接受的最佳实践是避免显式地调用GC(所谓的“系统GC”),即在应用程序中调用system.gc()。
//然而,这个建议是不管使用的GC算法的,值得一提的是,当使用CMS收集器时,系统GC将是一件很不幸的事,
//因为它默认会触发一次Full GC。幸运的是,有一种方式可以改变默认设置。
//标志-XX:+ExplicitGCInvokesConcurrent命令JVM无论什么时候调用系统GC,都执行CMS GC,而不是Full GC。
//第二个标志-XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses保证当有系统GC调用时,
//永久代也被包括进CMS垃圾回收的范围内。因此,通过使用这些标志,我们可以防止出现意料之外的”stop-the-world”的系统GC。
-XX:+ExplicitGCInvokesConcurrent
-XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses
参考网址 https://gceasy.io/ 进行GC日志分析
GC分析参考说明:
2022-02-23T08:53:15.874+0800: 61185.832: [Full GC (Allocation Failure) 31G->31G(32G), 114.9497988 secs]
[Eden: 0.0B(1632.0M)->0.0B(1632.0M) Survivors: 0.0B->0.0B Heap: 32.0G(32.0G)->31.8G(32.0G)], [metaspace: 46384K->46381K(49152K)]
Heap after GC invocations=7305 (full 115):
garbage-first heap total 33554432K, used 33391861K [0x00007f29ac000000, 0x00007f29ad004000, 0x00007f31ac000000)
region size 16384K, 0 young (0K), 0 survivors (0K)
metaspace used 46381K, capacity 47966K, committed 48384K, reserved 49152K
}
[Times: user=207.85 sys=0.00, real=114.95 secs]
2022-02-23T08:55:10.825+0800: 61300.782: Total time for which application threads were stopped: 114.9532648 seconds, Stopping threads took: 0.0001535 seconds
real time:GC事件整个过程自然流逝的绝对时间,这个跟钟表上的时间是一致的。(ps:如果GC从8点开始,8点30结束,real time就是30分钟)。
user time:cpu花在用户态的时间
sys time:cpu花在内核态的时间,也就是说内核发生系统调用所花费的时间,不包括调用lib库的时间,因为这是发生在用户态。
一般来说,GC事件中user time是大于sys time的,因为在发生GC的时候,大部分时间是在执行JVM的代码,只有很少的时间用在内核中。但是,有时候是会发生sys time比user time长的场景。
日志解读(属于个人解读,如果有误,请各位大佬指正):
日志中 real=114.95 与Total time for which application threads were stopped说明需要对JVM进行优化如果这里real时间与 Total time for which application threads were stopped对应不上,那么应该考虑safepoint问题(请参考浅析 JVM Safepoint 以及 Stop The World - 墨天轮)如果单独sys时间大 要考虑系统1.操作系统的问题
操作系统出现诸如缺页、未对齐的内存引用、浮点数异常这样的问题的时候就会花费大量的sys time,要确保你的操作系统打好了补丁,升级了最新版本,有足够的cpu、内存、磁盘空间。
2.虚拟机相关问题
如果你的应用是运行在虚拟化环境中,可能会出现sys time比user time长,要确保虚拟化环境不因为环境多而过载,同时要确保给运行你应用的虚拟机分配了足够的资源。
3.内存限制
在linux系统上,JVM和操作系统都可能会申请大的内存页(比如2M/页),如果操作系统找不到连续的空闲内存来分配2M的页,那它就会把所有运行的进程全都暂停掉,然后整理内存以找到连续的空闲内存。如果操作系统是在做这个事情,那么sys time就会比real time还要大。如果出现了这种情况,要么就给机器分配足够的内存,要么就减少机器上运行的进程数量。
4.磁盘IO的压力
JVM会把安全点和GC事件的统计信息写到/tmp/hsperfdata_(username) 文件中,当发生GC的时候就会更新这个文件。当磁盘的IO负载比较高的时候,内核线程可能会阻塞GC线程更新这个文件。因此如果磁盘的IO负载非常重的话是有可能增加GC的停顿时间的。如果发生了这种情况,要么real time远大于sys time+user time,要么sys time远大于user time。此时,就需要降低磁盘的IO负载才可以。可以用lsof来查看磁盘的IO负载情况。