[jira] [Commented] (CASSANDRA-20607) Gossip thread slows down when forceBlockingFlush is called on system.peers and system.peers_v2 tables

["Stefan Miklosovic (Jira)" <ji...@apache.org>]

    [ https://issues.apache.org/jira/browse/CASSANDRA-20607?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=18125383#comment-18125383 ] 

Stefan Miklosovic commented on CASSANDRA-20607:
-----------------------------------------------

We have a customer who also looks very similar if not the same thing:

We’re seeing this issue with one of the XXX Production cluster. To start with this cluster has two datacenter one in US and the other in EU. We are carrying out the activity to replace the nodes on the US datacenter to the new CIDR range, thus there is change in the IPs of the node.  

The issue we’re seeing at this stage is, the peer nodes are being marked down after the replaced node joins the cluster with the new IP.  Attaching metrics after the node is replaced and cassandra is up on the new node. 

Pending Gossiptasks  We took the thread dumps on the nodes which were showing this sign of high pending gossiptasks.  What we observed, the thread dumps are showing GossipStage is stuck while flushing the peers table (cause we’re replacing node with the new IP so, the peers tables needs to be updating), so its waiting for the MemtablePostFlush, and MemtablePostFlush is waiting for the MemtableFlushWriter which appears to be building the SSTableIntervalTree on all the threaddumps. Thats where we got up to looking at the issue.  

The node that was replaced didn’t see any of this issue, it was just the peer nodes on the another region EU.  About this cluster, it has two datacenter, US-> has 315 nodes and EU -> has 144 nodes. The peer nodes that is being marked down and shows the sign of high pending gossip tasks and the issue we’re seeing here is in the EU region.  We’ve attached all the thread dumps we were able to capture for the node we saw this issue with.

> Gossip thread slows down when forceBlockingFlush is called on system.peers and system.peers_v2 tables
> -----------------------------------------------------------------------------------------------------
>
>                 Key: CASSANDRA-20607
>                 URL: https://issues.apache.org/jira/browse/CASSANDRA-20607
>             Project: Apache Cassandra
>          Issue Type: Bug
>            Reporter: Hieu Ngo
>            Priority: Normal
>             Fix For: 4.1.x, 5.0.x, 7.x
>
>
> The metrics system at Dropbox.com (Vortex2) uses cassandra as the data storage layer to store metric and metadata data. The system is undergoing a migration project to move cassandra hosted on premise to an in-house kubernetes-based deployment system.
> Whenever a pod running cassandra is rotated out during a deployment, we have seen many nodes deemed as Down Normal pretty much at the same time for a brief period (15 - 30s), resulting in excessive hints created, timed out and unavailable exceptions.
> It turns out that the bug is at the forceBlockingFlush call on system.peers and system.peers_v2 tables happening within the single-threaded Gossip Stage. The flush takes too long, occupying the Gossip STage and causing gossip tasks to pile up. Since gossip tasks aren't sent properly and timely, nodes in the system start marking other nodes as Down Normal. From the stack trace, we believe the forceBlockFlush is called as part of the host ip update when the rotated pod changes its IP.
> We have created a patch internally to change the flush to nonBlockingFlush if the flag cassandra.load_ring_state=false. The rationale for the fix is that since the ring state isn't loaded from those peers tables during startup, there is no need to wait for the flush. However, we haven't figured out why the blocking flush to system.peers and system.peers_v2 tables takes so long. 
> The asks for this bug are:
> 1. Figure out why blocking flush to system.peers and system.peers_v2 tables takes so long.
> 2. Create a fix to change the flush to non-blocking if cassandra.load_ring_state is set to false. We notice that the cassandra.load_ring_state is removed in cassandra 5.0 so the fix may only be applicable to 4.x and older versions.
>  
> Here is the stack trace of GossipStage:
>  
> {code:java}
> "GossipStage:1" #205 daemon prio=5 os_prio=0 cpu=113114.96ms elapsed=233376.38s tid=0x00007fad2002c480 nid=0x3a5 waiting on condition [0x00007faf9613d000]
> java.lang.Thread.State: WAITING (parking)
> at jdk.internal.misc.Unsafe.park(java.base@11.0.25/Native Method)
> at java.util.concurrent.locks.LockSupport.park(java.base@11.0.25/LockSupport.java:323)
> at org.apache.cassandra.utils.concurrent.WaitQueue$Standard$AbstractSignal.await(WaitQueue.java:289)
> at org.apache.cassandra.utils.concurrent.WaitQueue$Standard$AbstractSignal.await(WaitQueue.java:282)
> at org.apache.cassandra.utils.concurrent.Awaitable$AsyncAwaitable.await(Awaitable.java:306)
> at org.apache.cassandra.utils.concurrent.AsyncFuture.await(AsyncFuture.java:154)
> at org.apache.cassandra.utils.concurrent.AsyncFuture.await(AsyncFuture.java:46)
> at org.apache.cassandra.utils.concurrent.AbstractFuture.get(AbstractFuture.java:245)
> at org.apache.cassandra.utils.FBUtilities.waitOnFutures(FBUtilities.java:501)
> at org.apache.cassandra.utils.FBUtilities.waitOnFutures(FBUtilities.java:477)
> at org.apache.cassandra.db.SystemKeyspace.forceBlockingFlush(SystemKeyspace.java:947)
> at org.apache.cassandra.db.SystemKeyspace.removeEndpoint(SystemKeyspace.java:916)
> locked <0x0000000101dfccc0> (a java.lang.Class for org.apache.cassandra.db.SystemKeyspace)
> at org.apache.cassandra.service.StorageService.removeEndpoint(StorageService.java:3339)
> at org.apache.cassandra.service.StorageService.updateTokenMetadata(StorageService.java:3052)
> at org.apache.cassandra.service.StorageService.handleStateNormal(StorageService.java:3176)
> at org.apache.cassandra.service.StorageService.onChange(StorageService.java:2638)
> at org.apache.cassandra.gms.Gossiper.doOnChangeNotifications(Gossiper.java:1711)
> at org.apache.cassandra.service.StorageService.onJoin(StorageService.java:3652)
> at org.apache.cassandra.gms.Gossiper.handleMajorStateChange(Gossiper.java:1481)
> at org.apache.cassandra.gms.Gossiper.applyStateLocally(Gossiper.java:1627)
> at org.apache.cassandra.gms.GossipDigestAck2VerbHandler.doVerb(GossipDigestAck2VerbHandler.java:50)
> at org.apache.cassandra.net.InboundSink.lambda$new$0(InboundSink.java:78)
> at org.apache.cassandra.net.InboundSink$$Lambda$603/0x000000080069c040.accept(Unknown Source)
> at org.apache.cassandra.net.InboundSink.accept(InboundSink.java:97)
> at org.apache.cassandra.net.InboundSink.accept(InboundSink.java:45)
> at org.apache.cassandra.net.InboundMessageHandler$ProcessMessage.run(InboundMessageHandler.java:430)
> at org.apache.cassandra.concurrent.ExecutionFailure$1.run(ExecutionFailure.java:133)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.25/ThreadPoolExecutor.java:1128)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.25/ThreadPoolExecutor.java:628)
> at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
> at java.lang.Thread.run(java.base@11.0.25/Thread.java:829)
>  {code}
>  
> Here is the PerDiskMemtableFlushWriter that the GossipStage was waiting for:
>  
> {code:java}
> "PerDiskMemtableFlushWriter_0:470" #170632 daemon prio=5 os_prio=0 cpu=42316.16ms elapsed=44.53s tid=0x00007faee40c91c0 nid=0x79f5 runnable [0x00007faf70613000]
> java.lang.Thread.State: RUNNABLE
> at org.apache.cassandra.db.marshal.AbstractType.writeValue(AbstractType.java:469)
> at org.apache.cassandra.db.ClusteringPrefix$Serializer.serializeValuesWithoutSize(ClusteringPrefix.java:397)
> at org.apache.cassandra.db.Clustering$Serializer.serialize(Clustering.java:133)
> at org.apache.cassandra.db.rows.UnfilteredSerializer.serialize(UnfilteredSerializer.java:188)
> at org.apache.cassandra.db.rows.UnfilteredSerializer.serialize(UnfilteredSerializer.java:137)
> at org.apache.cassandra.db.ColumnIndex.add(ColumnIndex.java:258)
> at org.apache.cassandra.db.ColumnIndex.buildRowIndex(ColumnIndex.java:122)
> at org.apache.cassandra.io.sstable.format.big.BigTableWriter.append(BigTableWriter.java:222)
> at org.apache.cassandra.io.sstable.SimpleSSTableMultiWriter.append(SimpleSSTableMultiWriter.java:48)
> at org.apache.cassandra.db.memtable.Flushing$FlushRunnable.writeSortedContents(Flushing.java:163)
> at org.apache.cassandra.db.memtable.Flushing$FlushRunnable.call(Flushing.java:183)
> at org.apache.cassandra.db.memtable.Flushing$FlushRunnable.call(Flushing.java:122)
> at org.apache.cassandra.concurrent.FutureTask.call(FutureTask.java:61)
> at org.apache.cassandra.concurrent.FutureTask.run(FutureTask.java:71)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.25/ThreadPoolExecutor.java:1128)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.25/ThreadPoolExecutor.java:628)
> at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
> at java.lang.Thread.run(java.base@11.0.25/Thread.java:829) {code}
>  



--
This message was sent by Atlassian Jira
(v8.20.10#820010)

---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@cassandra.apache.org
For additional commands, e-mail: commits-help@cassandra.apache.org