Cassandra 升级创建物化视图失败解决 + JVM调优

背景说明

公司项目现有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秒

针对两个问题分别进行优化处理

1. 墓碑数据

执行/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长的场景。

日志解读（属于个人解读，如果有误，请各位大佬指正）：

1. 日志中 real=114.95 与Total time for which application threads were stopped说明需要对JVM进行优化
2. 如果这里real时间与 Total time for which application threads were stopped对应不上，那么应该考虑safepoint问题（请参考浅析 JVM Safepoint 以及 Stop The World - 墨天轮）
3. 如果单独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负载情况。