Node hanging, huge heap usage

Question

question

denis.koblov asked Mar 21, '21 denis.koblov commented Mar 31, '21

Node hanging, huge heap usage

Hey, guys. I need your help))

Sometimes one of the cassandra nodes (3.11.2 version) starts behaving strangely. In particular:

System CPU usage:

IO wait:

снимок-экрана-2021-03-21-в-013431.png

During this period, the outgoing traffic of the node fell down:

снимок-экрана-2021-03-21-в-013719.png

And there were a lot of records like 'Timeout while read-repairing after receiving all 6 data and digest' in the logs.

If we look at the usage of mapped memory, we see the following:

снимок-экрана-2021-03-21-в-013558.png

The spikes before the anomaly correlates with the compaction activity:

снимок-экрана-2021-03-21-в-013831.png

In addition, the heap usage has reached almost 100% (32 GB).

снимок-экрана-2021-03-21-в-115204.png

As a result, GC worked a lot:

снимок-экрана-2021-03-21-в-134006.png

In my opinion, the GC work is the cause of node unavailability, but why was the heap and mapped memory used a lot (unfortunately, I wasn't able to get a heap dump)?

From 15: 44:40 to 15:44:50 (when the CPU usage fell down), there are only these records in the logs:

15:44:42.499Z host DEBUG [COMMIT-LOG-ALLOCATOR] o.a.c.d.c.AbstractCommitLogSegmentManager - [] No segments in reserve; creating a fresh one
15:44:43.357Z host DEBUG [cluster2-nio-worker-0] com.datastax.driver.core.Connection - [] Connection[/<local_ip>:9042-1, inFlight=0, closed=false] was inactive for 30 seconds, sending heartbeat
15:44:43.358Z host DEBUG [cluster2-nio-worker-0] com.datastax.driver.core.Connection - [] Connection[/<local_ip>:9042-1, inFlight=0, closed=false] heartbeat query succeeded
OCATOR] o.a.c.d.c.AbstractCommitLogSegmentManager - [] No segments in reserve; creating a fresh one
15:44:45.242Z host DEBUG [CompactionExecutor:9] o.a.c.db.compaction.CompactionTask - [] Compacted (11239242-88c9-11eb-9287-ed8c5d87e5c3) 2 sstables to [/data/data/my_table-b4108710c1cc11e6bbea6739e6451df9/mc-3647-big,] to level=0.  6.954GiB to 5.983GiB (~86% of original) in 413,012ms.  Read Throughput = 17.241MiB/s, Write Throughput = 14.833MiB/s, Row Throughput = ~121,513/s.  14,009,430 total partitions merged to 11,084,640.  Partition merge counts were {1:8205824, 2:2901803, }
15:44:45.250Z host DEBUG [CompactionExecutor:9] o.a.c.db.compaction.CompactionTask - [] Compacting (07519311-88ca-11eb-9287-ed8c5d87e5c3) [/data/data/my_table-b4108710c1cc11e6bbea6739e6451df9/mc-3650-big-Data.db:level=0, /data/data/my_table-b4108710c1cc11e6bbea6739e6451df9/mc-3651-big-Data.db:level=0, /data/data/my_table-b4108710c1cc11e6bbea6739e6451df9/mc-3649-big-Data.db:level=0, /data/data/my_table-b4108710c1cc11e6bbea6739e6451df9/mc-3652-big-Data.db:level=0, ]
15:44:46.183Z host INFO [Service Thread] o.a.cassandra.service.GCInspector - [] G1 Young Generation GC in 222ms.  G1 Eden Space: 8606711808 -> 0; G1 Old Gen: 15180859000 -> 15167382432; G1 Survivor Space: 218103808 -> 536870912; 
15:44:47.841Z host DEBUG [COMMIT-LOG-ALLOCATOR] o.a.c.d.c.AbstractCommitLogSegmentManager - [] No segments in reserve; creating a fresh one

The compaction task 07519311-88ca-11eb-9287-ed8c5d87e5c3 was completed at 15:46:36 After that the next compaction task was started and there is no record about finishing this task (it wasn't completed by the time of the manual node restart at 16:10)

...
15:46:35.957Z host DEBUG [Native-Transport-Requests-288] o.a.c.service.ResponseResolver - [] Timeout while read-repairing after receiving all 6 data and digest responses
15:46:35.974Z host DEBUG [Native-Transport-Requests-432] o.a.c.service.ResponseResolver - [] Timeout while read-repairing after receiving all 6 data and digest responses
15:46:36.249Z host DEBUG [CompactionExecutor:9] o.a.c.db.compaction.CompactionTask - [] Compacted (07519311-88ca-11eb-9287-ed8c5d87e5c3) 4 sstables to [/data/data/my_table-b4108710c1cc11e6bbea6739e6451df9/mc-3653-big,] to level=0.  1.204GiB to 1.135GiB (~94% of original) in 76,400ms.  Read Throughput = 16.132MiB/s, Write Throughput = 15.208MiB/s, Row Throughput = ~108,350/s.  3,995,772 total partitions merged to 3,379,549.  Partition merge counts were {1:2948311, 2:300597, 3:76297, 4:54344, }
15:46:36.298Z host DEBUG [ReadRepairStage:741] o.a.c.service.ResponseResolver - [] Timeout while read-repairing after receiving all 1 data and digest responses
15:46:36.300Z host DEBUG [CompactionExecutor:9] o.a.c.db.compaction.CompactionTask - [] Compacting (497de1d0-88ca-11eb-9287-ed8c5d87e5c3) [/data/data/my_table-b4108710c1cc11e6bbea6739e6451df9/mc-3653-big-Data.db:level=0, /data/data/my_table-b4108710c1cc11e6bbea6739e6451df9/mc-3647-big-Data.db:level=0, ]
...

My compaction strategy is LeveledCompactionStrategy.

I am not sure if the root cause of the issue is compaction, because in general it works fast enough without affecting the node works. But then what could be the cause for this behavior?

Thank you in advance for your help.

performance

снимок-экрана-2021-03-21-в-013303.png (528.8 KiB)

снимок-экрана-2021-03-21-в-013431.png (662.7 KiB)

снимок-экрана-2021-03-21-в-013719.png (693.1 KiB)

снимок-экрана-2021-03-21-в-013558.png (677.3 KiB)

снимок-экрана-2021-03-21-в-013831.png (806.0 KiB)

снимок-экрана-2021-03-21-в-115204.png (572.8 KiB)

снимок-экрана-2021-03-21-в-134006.png (363.6 KiB)

10 |1000

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

DataStax Enterprise is powered by the best distribution of Apache Cassandra ™

Apache, Apache Cassandra, Cassandra, Apache Tomcat, Tomcat, Apache Lucene, Lucene, Apache Solr, Apache Hadoop, Hadoop, Apache Spark, Spark, Apache TinkerPop, TinkerPop, Apache Kafka and Kafka are either registered trademarks or trademarks of the Apache Software Foundation or its subsidiaries in Canada, the United States and/or other countries.

Privacy Policy Terms of Use

Answer 1 · 2021-03-22T06:56:29Z

Erick Ramirez answered Mar 22, '21 denis.koblov commented Mar 31, '21

The symptoms you described are typically caused by nodes being overloaded with app traffic.

In my experience, high CPU usage is almost always caused by high GC churn, high IO waits or both.

In relation to the high mapped memory, data files are cached with mmap() to make reads faster. Typically, you only want to map the index files so as not to run out of memory on the nodes (see Why nodes run out of memory after upgrading Cassandra). But the important thing to note is that the files are cached when they are read -- the fact that the mapped memory usage is high just indicates that a lot of data files are being read by Cassandra to satisfy read requests.

If the issue you reported is only occurring on one node then there is insufficient information from what you have provided so far to indicate the root cause so start looking into your application monitoring to see whether there has been a spike (or significant increase) in traffic that would account for the high load. Cheers!

10 Share

10 |1000

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

denis.koblov commented · Mar 22, 2021 at 09:00 AM

whether there has been a spike (or significant increase) in traffic that would account for the high load.

No, there were no any spikes in the traffic:

снимок-экрана-2021-03-22-в-115023.png

In addition, such cases happens in a milder form during the low traffic period.

What I mean by "in a milder form":

the request latency to the cassandra node increases;
the other nodes lose connections with suspected node;
the number of the hints increases.

It is happening for 5 minutes and after that return to the normal state.

For example, mapped memory usage in such case:

снимок-экрана-2021-03-22-в-164217.png

0 ·

снимок-экрана-2021-03-22-в-115023.png (515.4 KiB)

снимок-экрана-2021-03-22-в-164217.png (594.6 KiB)

Erick Ramirez ♦♦ denis.koblov commented · Mar 22, 2021 at 09:24 PM

If it's just happening on one node, I don't have enough information to know what is causing it. Sorry.

0 ·

Erick Ramirez ♦♦ denis.koblov commented · Mar 22, 2021 at 11:04 PM

I've been thinking about this. I think the IO wait is an important clue here. If it's just happening on one node, is it possible that there's a problem with the disk?

0 ·

denis.koblov Erick Ramirez ♦♦ commented · Mar 23, 2021 at 07:25 AM

No, sorry to confuse you. This happens on one node at a time. At other times, this is also observed on other nodes, too.

We have an idea: We noticed that JVM mapped memory growth correlates with internal. MemtableReclaimMemory. At the time of the incident, there are no completed tasks in this pool, the number of active ones is always = 1 and the number of Pending ones is growing.

There is the following code in the Cassandra-all.jar:

private void reclaim(final Memtable memtable){
  
   final OpOrder.Barrier readBarrier = readOrdering.newBarrier();
   readBarrier.issue();
   postFlushTask.addListener(new WrappedRunnable(){
   public void runMayThrow(){
            readBarrier.await();
            memtable.setDiscarded();
        }
    }, reclaimExecutor);
}

We think, that readBarrier.await() is not released and is waiting for something. As a result, memtables are nott flushed and we observed an increase in JVM mapped memory (not system mapped) and then an increase in heap usage.

0 ·

Show more comments

question