Hi Bowen, would it be possible to share a full thread dump? Regards, Dmitry
On Tue, 5 Nov 2024 at 12:12, Bowen Song via user <user@cassandra.apache.org> wrote: > 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 > > > -- Dmitry Konstantinov
