Hi all,
We have a cluster running Cassandra 4.1.1. We are seeing the memtable
flush randomly getting stuck. This has happened twice in the last 10
days, to two different nodes in the same cluster. This started to happen
after we enabled CDC, and each time it got stuck, there was at least one
repair running involving the affected node.
The signs of the stuck memtable flush is most obvious from the
"StatusLogger" logs.
At the beginning, the MemtablePostFlush and MemtableFlushWriter got
stuck, they have 1 and 2 active tasks each, and a small number of
pending tasks.
INFO [ScheduledTasks:1] 2024-11-03 03:50:15,224 StatusLogger.java:65 -
Pool Name Active Pending Completed Blocked
All Time Blocked
INFO [ScheduledTasks:1] 2024-11-03 03:50:15,224 StatusLogger.java:69 -
ReadStage 0 0 34052333 0 0
INFO [ScheduledTasks:1] 2024-11-03 03:50:15,224 StatusLogger.java:69 -
CompactionExecutor 0 0 1019777 0 0
INFO [ScheduledTasks:1] 2024-11-03 03:50:15,224 StatusLogger.java:69 -
MutationStage 0 0 14930764 0 0
INFO [ScheduledTasks:1] 2024-11-03 03:50:15,224 StatusLogger.java:69 -
MemtableReclaimMemory 0 0 21877 0 0
INFO [ScheduledTasks:1] 2024-11-03 03:50:15,224 StatusLogger.java:69 -
PendingRangeCalculator 0 0 177
0 0
INFO [ScheduledTasks:1] 2024-11-03 03:50:15,224 StatusLogger.java:69 -
Repair#61 0 0 1344 0 0
INFO [ScheduledTasks:1] 2024-11-03 03:50:15,224 StatusLogger.java:69 -
GossipStage 0 0 889452 0 0
INFO [ScheduledTasks:1] 2024-11-03 03:50:15,224 StatusLogger.java:69 -
SecondaryIndexManagement 0 0 1
0 0
INFO [ScheduledTasks:1] 2024-11-03 03:50:15,224 StatusLogger.java:69 -
HintsDispatcher 0 0 19 0 0
INFO [ScheduledTasks:1] 2024-11-03 03:50:15,224 StatusLogger.java:69 -
Repair-Task 0 0 65 0 0
INFO [ScheduledTasks:1] 2024-11-03 03:50:15,224 StatusLogger.java:69 -
RequestResponseStage 0 0 44447834 0 0
INFO [ScheduledTasks:1] 2024-11-03 03:50:15,224 StatusLogger.java:69 -
Native-Transport-Requests 0 0 8967921
0 0
INFO [ScheduledTasks:1] 2024-11-03 03:50:15,224 StatusLogger.java:69 -
MigrationStage 0 0 5 0 0
INFO [ScheduledTasks:1] 2024-11-03 03:50:15,224 StatusLogger.java:69 -
MemtableFlushWriter 2 10 21781 0 0
INFO [ScheduledTasks:1] 2024-11-03 03:50:15,224 StatusLogger.java:69 -
MemtablePostFlush 1 11 47856 0 0
INFO [ScheduledTasks:1] 2024-11-03 03:50:15,224 StatusLogger.java:69 -
PerDiskMemtableFlushWriter_0 0 0 21769
0 0
INFO [ScheduledTasks:1] 2024-11-03 03:50:15,224 StatusLogger.java:69 -
Sampler 0 0 0 0 0
INFO [ScheduledTasks:1] 2024-11-03 03:50:15,224 StatusLogger.java:69 -
ValidationExecutor 0 0 36651 0 0
INFO [ScheduledTasks:1] 2024-11-03 03:50:15,224 StatusLogger.java:69 -
ViewBuildExecutor 0 0 0 0 0
INFO [ScheduledTasks:1] 2024-11-03 03:50:15,224 StatusLogger.java:69 -
InternalResponseStage 0 0 240 0 0
INFO [ScheduledTasks:1] 2024-11-03 03:50:15,224 StatusLogger.java:69 -
AntiEntropyStage 1 1773 120067 0 0
INFO [ScheduledTasks:1] 2024-11-03 03:50:15,224 StatusLogger.java:69 -
CacheCleanupExecutor 0 0 0 0 0
The number of pending tasks slowly grows larger over time, and the
number of completed tasks do not increase at all.
INFO [ScheduledTasks:1] 2024-11-03 16:33:05,941 StatusLogger.java:65 -
Pool Name Active Pending Completed Blocked
All Time Blocked
INFO [ScheduledTasks:1] 2024-11-03 16:33:05,941 StatusLogger.java:69 -
ReadStage 0 0 39905462 0 0
INFO [ScheduledTasks:1] 2024-11-03 16:33:05,941 StatusLogger.java:69 -
CompactionExecutor 0 0 1170100 0 0
INFO [ScheduledTasks:1] 2024-11-03 16:33:05,941 StatusLogger.java:69 -
MutationStage 0 0 16976992 0 0
INFO [ScheduledTasks:1] 2024-11-03 16:33:05,941 StatusLogger.java:69 -
Repair#76 0 0 0 0 0
INFO [ScheduledTasks:1] 2024-11-03 16:33:05,941 StatusLogger.java:69 -
Repair#74 0 0 0 0 0
INFO [ScheduledTasks:1] 2024-11-03 16:33:05,941 StatusLogger.java:69 -
Repair#72 0 0 0 0 0
INFO [ScheduledTasks:1] 2024-11-03 16:33:05,941 StatusLogger.java:69 -
GossipStage 0 0 1026877 0 0
INFO [ScheduledTasks:1] 2024-11-03 16:33:05,941 StatusLogger.java:69 -
Repair-Task 0 0 83 0 0
INFO [ScheduledTasks:1] 2024-11-03 16:33:05,941 StatusLogger.java:69 -
RequestResponseStage 0 0 51122191 0 0
INFO [ScheduledTasks:1] 2024-11-03 16:33:05,941 StatusLogger.java:69 -
ValidationExecutor 0 0 36651 0 0
INFO [ScheduledTasks:1] 2024-11-03 16:33:05,941 StatusLogger.java:69 -
MemtablePostFlush 1 54 47856 0 0
INFO [ScheduledTasks:1] 2024-11-03 16:33:05,941 StatusLogger.java:69 -
MemtableFlushWriter 2 53 21781 0 0
INFO [ScheduledTasks:1] 2024-11-03 16:33:05,941 StatusLogger.java:69 -
CacheCleanupExecutor 0 0 0 0 0
INFO [ScheduledTasks:1] 2024-11-03 16:33:05,941 StatusLogger.java:69 -
Repair#67 0 0 0 0 0
INFO [ScheduledTasks:1] 2024-11-03 16:33:05,941 StatusLogger.java:69 -
MemtableReclaimMemory 0 0 21877 0 0
INFO [ScheduledTasks:1] 2024-11-03 16:33:05,941 StatusLogger.java:69 -
PendingRangeCalculator 0 0 177
0 0
INFO [ScheduledTasks:1] 2024-11-03 16:33:05,941 StatusLogger.java:69 -
Repair#82 0 0 0 0 0
INFO [ScheduledTasks:1] 2024-11-03 16:33:05,941 StatusLogger.java:69 -
Repair#61 0 0 1344 0 0
INFO [ScheduledTasks:1] 2024-11-03 16:33:05,941 StatusLogger.java:69 -
SecondaryIndexManagement 0 0 1
0 0
INFO [ScheduledTasks:1] 2024-11-03 16:33:05,941 StatusLogger.java:69 -
HintsDispatcher 0 0 20 0 0
INFO [ScheduledTasks:1] 2024-11-03 16:33:05,941 StatusLogger.java:69 -
Native-Transport-Requests 0 0 10145020
0 0
INFO [ScheduledTasks:1] 2024-11-03 16:33:05,941 StatusLogger.java:69 -
MigrationStage 0 0 5 0 0
INFO [ScheduledTasks:1] 2024-11-03 16:33:05,941 StatusLogger.java:69 -
Sampler 0 0 0 0 0
INFO [ScheduledTasks:1] 2024-11-03 16:33:05,941 StatusLogger.java:69 -
PerDiskMemtableFlushWriter_0 0 0 21769
0 0
INFO [ScheduledTasks:1] 2024-11-03 16:33:05,942 StatusLogger.java:69 -
ViewBuildExecutor 0 0 0 0 0
INFO [ScheduledTasks:1] 2024-11-03 16:33:05,942 StatusLogger.java:69 -
InternalResponseStage 0 0 996 0 0
INFO [ScheduledTasks:1] 2024-11-03 16:33:05,942 StatusLogger.java:69 -
AntiEntropyStage 1 9694 120067 0 0
Then, things start to get worse, the MutationStage also got stuck.
INFO [ScheduledTasks:1] 2024-11-03 17:05:40,974 StatusLogger.java:65 -
Pool Name Active Pending Completed Blocked
All Time Blocked
INFO [ScheduledTasks:1] 2024-11-03 17:05:40,974 StatusLogger.java:69 -
ReadStage 0 0 40186426 0 0
INFO [ScheduledTasks:1] 2024-11-03 17:05:40,974 StatusLogger.java:69 -
CompactionExecutor 0 0 1171479 0 0
INFO [ScheduledTasks:1] 2024-11-03 17:05:40,974 StatusLogger.java:69 -
MutationStage 128 201414 16988212
0 0
INFO [ScheduledTasks:1] 2024-11-03 17:05:40,974 StatusLogger.java:69 -
Repair#76 0 0 0 0 0
INFO [ScheduledTasks:1] 2024-11-03 17:05:40,974 StatusLogger.java:69 -
Repair#74 0 0 0 0 0
INFO [ScheduledTasks:1] 2024-11-03 17:05:40,974 StatusLogger.java:69 -
Repair#72 0 0 0 0 0
INFO [ScheduledTasks:1] 2024-11-03 17:05:40,974 StatusLogger.java:69 -
GossipStage 0 0 1032988 0 0
INFO [ScheduledTasks:1] 2024-11-03 17:05:40,974 StatusLogger.java:69 -
Repair-Task 0 0 85 0 0
INFO [ScheduledTasks:1] 2024-11-03 17:05:40,974 StatusLogger.java:69 -
RequestResponseStage 0 0 51307497 0 0
INFO [ScheduledTasks:1] 2024-11-03 17:05:40,974 StatusLogger.java:69 -
ValidationExecutor 0 0 36651 0 0
INFO [ScheduledTasks:1] 2024-11-03 17:05:40,974 StatusLogger.java:69 -
MemtablePostFlush 1 54 47856 0 0
INFO [ScheduledTasks:1] 2024-11-03 17:05:40,974 StatusLogger.java:69 -
MemtableFlushWriter 2 53 21781 0 0
INFO [ScheduledTasks:1] 2024-11-03 17:05:40,974 StatusLogger.java:69 -
CacheCleanupExecutor 0 0 0 0 0
INFO [ScheduledTasks:1] 2024-11-03 17:05:40,974 StatusLogger.java:69 -
Repair#67 0 0 0 0 0
INFO [ScheduledTasks:1] 2024-11-03 17:05:40,974 StatusLogger.java:69 -
MemtableReclaimMemory 0 0 21877 0 0
INFO [ScheduledTasks:1] 2024-11-03 17:05:40,974 StatusLogger.java:69 -
Repair#84 0 0 0 0 0
INFO [ScheduledTasks:1] 2024-11-03 17:05:40,974 StatusLogger.java:69 -
PendingRangeCalculator 0 0 177
0 0
INFO [ScheduledTasks:1] 2024-11-03 17:05:40,974 StatusLogger.java:69 -
Repair#82 0 0 0 0 0
INFO [ScheduledTasks:1] 2024-11-03 17:05:40,974 StatusLogger.java:69 -
Repair#61 0 0 1344 0 0
INFO [ScheduledTasks:1] 2024-11-03 17:05:40,974 StatusLogger.java:69 -
SecondaryIndexManagement 0 0 1
0 0
INFO [ScheduledTasks:1] 2024-11-03 17:05:40,974 StatusLogger.java:69 -
HintsDispatcher 0 0 20 0 0
INFO [ScheduledTasks:1] 2024-11-03 17:05:40,974 StatusLogger.java:69 -
Native-Transport-Requests 0 0 10194549
0 0
INFO [ScheduledTasks:1] 2024-11-03 17:05:40,974 StatusLogger.java:69 -
MigrationStage 0 0 5 0 0
INFO [ScheduledTasks:1] 2024-11-03 17:05:40,974 StatusLogger.java:69 -
Sampler 0 0 0 0 0
INFO [ScheduledTasks:1] 2024-11-03 17:05:40,974 StatusLogger.java:69 -
PerDiskMemtableFlushWriter_0 0 0 21769
0 0
INFO [ScheduledTasks:1] 2024-11-03 17:05:40,974 StatusLogger.java:69 -
ViewBuildExecutor 0 0 0 0 0
INFO [ScheduledTasks:1] 2024-11-03 17:05:40,974 StatusLogger.java:69 -
InternalResponseStage 0 0 1087 0 0
INFO [ScheduledTasks:1] 2024-11-03 17:05:40,974 StatusLogger.java:69 -
AntiEntropyStage 1 10364 120067 0 0
Writes on this node starts to timeout and fail. But if left untouched,
it's only gonna get worse, and eventually lead to JVM OOM and crash.
By inspecting the heap dump created at OOM, we can see that both of the
MemtableFlushWriter threads are stuck on line 1190
<https://github.com/apache/cassandra/blob/8d91b469afd3fcafef7ef85c10c8acc11703ba2d/src/java/org/apache/cassandra/db/ColumnFamilyStore.java#L1190>
in the ColumnFamilyStore.java:
// mark writes older than the barrier as blocking progress,
permitting them to exceed our memory limit
// if they are stuck waiting on it, then wait for them all
to complete
writeBarrier.markBlocking();
writeBarrier.await(); // <----------- stuck here
And the MemtablePostFlush thread is stuck on line 1094
<https://github.com/apache/cassandra/blob/8d91b469afd3fcafef7ef85c10c8acc11703ba2d/src/java/org/apache/cassandra/db/ColumnFamilyStore.java#L1094>
in the same file.
try
{
// we wait on the latch for the commitLogUpperBound to
be set, and so that waiters
// on this task can rely on all prior flushes being
complete
latch.await();// <----------- stuck here
}
Our top suspect is CDC interacting with repair, since this started to
happen shortly after we enabled CDC on the nodes, and each time repair
was running. But we have not been able to reproduce this in a testing
cluster, and don't know what's the next step to troubleshoot this issue.
So I'm posting it in the mailing lists and hoping someone may know
something about it or point me to the right direction.
p.s.: sorry about posting this to both the user & dev mailing lists.
It's an end-user related issue but involves Cassandra internals, so I
can't decide which one is best suited.
Cheers,
Bowen
