question

adityajain22_141041 avatar image
adityajain22_141041 asked Erick Ramirez commented

Sudden CPU spike on all nodes in the cluster when a node suffering from disk issues became unresponsive

We have a 6 node cluster,

one node was unresponsive due to some disk io issue. and suddenly i can see CPU hike on all nodes like cassandra usking 2983% of single cpu

top - 14:16:32 up 470 days, 17:47, 17 users, load average: 0.76, 0.91, 0.97
Tasks: 622 total, 1 running, 621 sleeping, 0 stopped, 0 zombie
%Cpu(s): 68.6 us, 0.8 sy, 0.0 ni, 30.5 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem : 19778848+total, 16743604 free, 47336320 used, 13370856+buff/cache
KiB Swap: 0 total, 0 free, 0 used. 13870702+avail Mem

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
110807 cassand+ 20 0 231.0g 83.6g 44.5g S 2934 44.3 17338:05 java

system.log-----

ERROR [ReadRepairStage:30637] 2020-02-27 14:16:22,153 CassandraDaemon.java:228 - Exception in thread Thread[ReadRepairStage:30637,5,main]
org.apache.cassandra.exceptions.ReadTimeoutException: Operation timed out - received only 0 responses.
    at org.apache.cassandra.service.DataResolver$RepairMergeListener.close(DataResolver.java:202) ~[apache-cassandra-3.11.2.jar:3.11.2]
    at org.apache.cassandra.db.partitions.UnfilteredPartitionIterators$2.close(UnfilteredPartitionIterators.java:175) ~[apache-cassandra-3.11.2.jar:3.11.2]
    at org.apache.cassandra.db.transform.BaseIterator.close(BaseIterator.java:92) ~[apache-cassandra-3.11.2.jar:3.11.2]
    at org.apache.cassandra.service.DataResolver.compareResponses(DataResolver.java:79) ~[apache-cassandra-3.11.2.jar:3.11.2]
    at org.apache.cassandra.service.AsyncRepairCallback$1.runMayThrow(AsyncRepairCallback.java:50) ~[apache-cassandra-3.11.2.jar:3.11.2]
    at org.apache.cassandra.utils.WrappedRunnable.run(WrappedRunnable.java:28) ~[apache-cassandra-3.11.2.jar:3.11.2]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[na:1.8.0_221]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[na:1.8.0_221]
    at org.apache.cassandra.concurrent.NamedThreadFactory.lambda$threadLocalDeallocator$0(NamedThreadFactory.java:81) ~[apache-cassandra-3.11.2.jar:3.11.2]
    at java.lang.Thread.run(Thread.java:748) ~[na:1.8.0_221]
INFO [HintsDispatcher:7] 2020-02-27 14:16:36,187 HintsStore.java:126 - Deleted hint file 27921b23-6bc0-48b4-bf6f-898aaabb6bc0-1582793184685-1.hints
INFO [HintsDispatcher:7] 2020-02-27 14:16:36,187 HintsDispatchExecutor.java:282 - Finished hinted handoff of file 27921b23-6bc0-48b4-bf6f-898aaabb6bc0-1582793184685-1.hints to endpoint /BADNODE-IP: 27921b23-6bc0-48b4-bf6f-898aaabb6bc0
INFO [HintsDispatcher:7] 2020-02-27 14:16:36,550 HintsStore.java:126 - Deleted hint file 27921b23-6bc0-48b4-bf6f-898aaabb6bc0-1582793194687-1.hints
INFO [HintsDispatcher:7] 2020-02-27 14:16:36,550 HintsDispatchExecutor.java:282 - Finished hinted handoff of file 27921b23-6bc0-48b4-bf6f-898aaabb6bc0-1582793194687-1.hints to endpoint /BADNODE-IP: 27921b23-6bc0-48b4-bf6f-898aaabb6bc0

Was other node CPU were so high because of hinted handoff work??

we could not find why other nodes were miss behaving?

cassandracpu
10 |1000
Toggle Comment visibility. Current Visibility: Viewable by all users

Up to 8 attachments (including images) can be used with a maximum of 1.0 MiB each and 10.0 MiB total.

1 Answer

Erick Ramirez avatar image
Erick Ramirez answered Erick Ramirez commented

@adityajain22_141041 The hints are only handed off to an unresponsive node after it comes back online. If this happened during a high traffic period, the most likely scenario is that the requests were queued up momentarily chewing up CPU cycles while waiting for requests to the problematic node to timeout.

Unfortunately, it's impossible to know what was going on at the time unless you managed to do a thread dump while the CPU utilisation was high. However in my experience, the scenario I described above is what happens in most cases. The requests to a problematic needs to reach the timeout threshold for them to be abandoned so there will always be a few seconds of impact in the cluster whenever a node becomes unresponsive. Cheers!

2 comments Share
10 |1000
Toggle Comment visibility. Current Visibility: Viewable by all users

Up to 8 attachments (including images) can be used with a maximum of 1.0 MiB each and 10.0 MiB total.

adityajain22_141041 avatar image adityajain22_141041 commented ·

@Erick Ramirez Thanks Eric, There was normal traffic and yes we can see the que build up as Native transport request were reached maxout and can see huge number in pending and block starte.

We are looking for a cause what triggered it to happen so, as stated load was normal.

0 Likes 0 ·
Erick Ramirez avatar image Erick Ramirez ♦♦ adityajain22_141041 commented ·

As I stated previously, the request queue would build up waiting for the problematic node to timeout. That happens when a node is not completely down. If the node crashed completely and there were no processes listening on the ports, it would timeout immediately. That's just how daemons behave in general, not specific to C*. Cheers!

0 Likes 0 ·