Bringing together the Apache Cassandra experts from the community and DataStax.

Want to learn? Have a question? Want to share your expertise? You are in the right place!

Not sure where to begin? Getting Started

 

question

jordanp98 avatar image
jordanp98 asked ·

What do the GCInspector / StatusLogger messages mean?

I am using 2 node cluster for stress testing and learning purpose, both have 32 GB ram one acting as seed and the other as solr, during my use cases I found that queries are not running with error operation time out when I checked logs I found below entries seems like node oom issue but in logs, there was continuous lines like "INFO [GCInspector:1] 2020-12-31 06:13:45,807 StatusLogger.java:144 - Table Memtable ops, data" I just want to know the meaning of these logs or please help me to find if these are related to GC pauses?

INFO  [GCInspector:1] 2020-12-31 06:13:45,806  BufferPoolFactory.java:122 - Buffer pool size for cached reads: 9.886GiB, for direct reads: 8.000MiB
INFO  [GCInspector:1] 2020-12-31 06:13:45,806  BufferPoolFactory.java:126 - Cached reads buffer pool BufferPool for long lived buffers: Size-tiered from 4.000KiB to 4.000KiB buffers, using 1024 buffers per slab.
Sub pools:
Buffer size 4.000KiB: 5.820GiB used, 5.820GiB allocated, 1490 slabs.
Overflow: 4.065GiB
INFO  [GCInspector:1] 2020-12-31 06:13:45,806  BufferPoolFactory.java:127 - Direct reads buffer pool BufferPool for temporary buffers: allocated 8.000MiB, used 0.000KiB, overflow 0.000KiB, overflow allocations mean
 rate 0.000004
INFO  [GCInspector:1] 2020-12-31 06:13:45,806  StatusLogger.java:118 - Global memtable buffer pool size: onHeap = 58.148MiB, offHeap = 115.107MiB
INFO  [GCInspector:1] 2020-12-31 06:13:45,806  StatusLogger.java:129 - Cache Type                     Size                 Capacity               KeysToSave
INFO  [GCInspector:1] 2020-12-31 06:13:45,806  StatusLogger.java:131 - KeyCache                          0                104857600                      all
INFO  [GCInspector:1] 2020-12-31 06:13:45,807  StatusLogger.java:137 - RowCache                          0                        0                      all
INFO  [GCInspector:1] 2020-12-31 06:13:45,807  StatusLogger.java:144 - Table                       Memtable ops,data
INFO  [GCInspector:1] 2020-12-31 06:13:45,807  StatusLogger.java:147 - system_schema.columns                     0,0
INFO  [GCInspector:1] 2020-12-31 06:13:45,807  StatusLogger.java:147 - system_schema.types                       0,0
INFO  [GCInspector:1] 2020-12-31 06:13:45,807  StatusLogger.java:147 - system_schema.indexes                     0,0
INFO  [GCInspector:1] 2020-12-31 06:13:45,807  StatusLogger.java:147 - system_schema.keyspaces                   0,0
INFO  [GCInspector:1] 2020-12-31 06:13:45,807  StatusLogger.java:147 - system_schema.dropped_columns                 0,0
INFO  [GCInspector:1] 2020-12-31 06:13:45,807  StatusLogger.java:147 - system_schema.hidden_columns                 0,0
INFO  [GCInspector:1] 2020-12-31 06:13:45,807  StatusLogger.java:147 - system_schema.aggregates                  0,0
INFO  [GCInspector:1] 2020-12-31 06:13:45,807  StatusLogger.java:147 - system_schema.triggers                    0,0
INFO  [GCInspector:1] 2020-12-31 06:13:45,807  StatusLogger.java:147 - system_schema.tables                      0,0
INFO  [GCInspector:1] 2020-12-31 06:13:45,807  StatusLogger.java:147 - system_schema.views                       0,0
INFO  [GCInspector:1] 2020-12-31 06:13:45,807  StatusLogger.java:147 - system_schema.functions                   0,0
INFO  [GCInspector:1] 2020-12-31 06:13:45,807  StatusLogger.java:147 - system.compaction_history            88,21564
INFO  [GCInspector:1] 2020-12-31 06:13:45,807  StatusLogger.java:147 - system.IndexInfo                          0,0
INFO  [GCInspector:1] 2020-12-31 06:13:45,808  StatusLogger.java:147 - system.repairs                            0,0
INFO  [GCInspector:1] 2020-12-31 06:13:45,808  StatusLogger.java:147 - system.size_estimates             6804,260072
INFO  [GCInspector:1] 2020-12-31 06:13:45,808  StatusLogger.java:147 - system.paxos                              0,0
INFO  [GCInspector:1] 2020-12-31 06:13:45,808  StatusLogger.java:147 - system.built_views                        0,0
INFO  [GCInspector:1] 2020-12-31 06:13:45,808  StatusLogger.java:147 - system.peer_events                        0,0
INFO  [GCInspector:1] 2020-12-31 06:13:45,808  StatusLogger.java:147 - system.range_xfers                        0,0
INFO  [GCInspector:1] 2020-12-31 06:13:45,808  StatusLogger.java:147 - system.peers                              0,0
INFO  [GCInspector:1] 2020-12-31 06:13:45,808  StatusLogger.java:147 - system.batches                            0,0
INFO  [GCInspector:1] 2020-12-31 06:13:45,824  StatusLogger.java:147 - keyspace2.table_foo                    0,0
DEBUG [CoreThread-1] 2020-12-31 06:13:46,190  NoSpamLogger.java:92 - Fetching property -Dcassandra.printHeapHistogramOnOutOfMemoryError=null default=null 
ERROR [CoreThread-1] 2020-12-31 06:13:46,191  VerbHandlers.java:77 - Unexpected error during execution of request READS.SINGLE_READ (582968804): /192.168.1.20 -> /192.168.1.20
java.lang.OutOfMemoryError: Direct buffer memory
        at java.nio.Bits.reserveMemory(Bits.java:694)
        at java.nio.DirectByteBuffer.<init>(DirectByteBuffer.java:123)
        at java.nio.ByteBuffer.allocateDirect(ByteBuffer.java:311)

        Suppressed: org.apache.cassandra.utils.flow.Flow$FlowException: Flow call chain:
        PartitionSubscription: TrieIndexSSTableReader(path='/var/lib/cassandra/data/keyspace2/table_bar-f2aadca130e511eb85e977935d3511aa/aa-130-bti-Data.db'), sstable reader: [SSTable reader class: org.apa
che.cassandra.io.sstable.format.trieindex.ForwardIndexedReader, position: -1, direction: 1, slice: 0, stage: NEEDS_SET_FOR_SLICE]
        merge child         
                at org.apache.cassandra.utils.flow.Flow.wrapException(Flow.java:2456)
                at org.apache.cassandra.utils.flow.Merge$Candidate.onError(Merge.java:513)
                at org.apache.cassandra.io.sstable.format.AsyncPartitionReader$PartitionSubscription.onError(AsyncPartitionReader.java:470)
                at org.apache.cassandra.io.sstable.format.AsyncPartitionReader.readWithRetry(AsyncPartitionReader.java:250)
logging
10 |1000 characters needed characters left characters exceeded
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 ·

Yes, the GCInspector logging is triggered based on the thresholds configured in cassandra.yaml.

By default GC messages are logged at INFO level when GC pauses take longer than 200ms and at ERROR level for pauses longer than 1000ms (1 second):

gc_log_threshold_in_ms: 200
gc_warn_threshold_in_ms: 1000

The GC messages are expected when you are stressing the nodes since there will be more GC events when nodes are under load. Cheers!

1 comment Share
10 |1000 characters needed characters left characters exceeded
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.

jordanp98 avatar image jordanp98 ·

Hi @Erick Ramirez thanks for the valuable help.

0 Likes 0 ·