Thank you for the response. Since the time of this question, we've
identified a number of areas that needed improving and have helped
things along quite a bit. To answer your question, we were seeing both
ParNew and CMS. There were no errors in the log, and all the nodes have
been up.
However, we are seeing one interesting issue. We are running a 6 node
cluster with a Replication Factor of 3. The nodes are pretty evenly
balanced. All reads and writes to Cassandra uses LOCAL_QUORUM
consistency. We are seeing a very interesting problem from the JMX
statistics. We discovered we had one column family with an extremely
high and unexpected write count. The writes to this column family are
done in conjunction with other writes to other column families such that
their numbers should be roughly equivalent, but they are off by a factor
of 10. We have yet to find anything in our code that could cause this
discrepancy in numbers.
What really interesting is that we see this behavior on only 5 of the 6
nodes in our cluster. On 5 of the 6 nodes, we see statistics indicating
we are writing two fast and this specific memtable is exceeding its
memtable 128M limit, while this one other node seems to be handling the
load ok (Memtables stay within their limites). Given our replication
factor, I'm not sure how this is possible.
Any hints on what might be causing this additional load? Are there
other activities in Cassandra might account for this increased load on a
single column family?
Any insights would be appreciated,
-Mike
On 12/4/2012 3:33 PM, aaron morton wrote:
For background, a discussion on estimating working set
http://www.mail-archive.com/user@cassandra.apache.org/msg25762.html .
You can also just look at the size of tenured heap after a CMS.
Are you seeing lots of ParNew or CMS ?
GC activity is a result of configuration *and* workload. Look in your
data model for wide rows, or long lived rows that get a lot of
deletes, and look in your code for large reads / writes (e.g.
sometimes we read 100,000 columns from a row).
The number that really jumps out at me below is the number of Pending
requests for the Message Service. 24,000+ pending requests.
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,702 StatusLogger.java
(line 89) MessagingService n/a 24,229
Technically speaking that ain't right.
The whole server looks unhappy.
Are there any errors in the logs ?
Are all the nodes up ?
A very blunt approach is to reduce the in_memory_compaction_limit and
the concurrent_compactors or compaction_throughput_mb_per_sec. This
reduces the impact compaction and repair have on the system and may
give you breathing space to look at other causes. Once you have a feel
for what's going on you can turn them up.
Hope that helps.
A
-----------------
Aaron Morton
Freelance Cassandra Developer
New Zealand
@aaronmorton
http://www.thelastpickle.com
On 5/12/2012, at 7:04 AM, Mike <mthero...@yahoo.com
<mailto:mthero...@yahoo.com>> wrote:
Hello,
Our Cassandra cluster has, relatively recently, started experiencing
memory pressure that I am in the midsts of diagnosing. Our system
has uneven levels of traffic, relatively light during the day, but
extremely heavy during some overnight processing. We have started
getting a message:
WARN [ScheduledTasks:1] 2012-12-04 09:08:58,579 GCInspector.java
(line 145) Heap is 0.7520105072262254 full. You may need to reduce
memtable and/or cache sizes. Cassandra will now flush up to the two
largest memtables to free up memory. Adjust
flush_largest_memtables_at threshold in cassandra.yaml if you don't
want Cassandra to do this automatically
I've started implementing some instrumentation to gather stats from
JMX to determine what is happening. However, last night, the
GCInspector was kind enough to log the information below. Couple of
things jumped out at me.
The maximum heap for the Cassandra is 4GB. We are running Cassandra
1.1.2, on a 6 node cluster, with a replication factor of 3. All our
queries use LOCAL_QUORUM consistency.
Adding up the caches + the memtable "data" in the trace below, comes
to under 600MB
The number that really jumps out at me below is the number of Pending
requests for the Message Service. 24,000+ pending requests.
Does this number represent the number of outstanding client requests
that this node is processing? If so, does this mean we potentially
have 24,000 responses being pulled into memory, thereby causing this
memory issue? What else should I look at?
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,585 StatusLogger.java
(line 57) Pool Name Active Pending Blocked
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,695 StatusLogger.java
(line 72) ReadStage 32 66 0
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,696 StatusLogger.java
(line 72) RequestResponseStage 0 193 0
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,696 StatusLogger.java
(line 72) ReadRepairStage 0 0 0
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,696 StatusLogger.java
(line 72) MutationStage 2 2 0
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,697 StatusLogger.java
(line 72) ReplicateOnWriteStage 5 5 0
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,698 StatusLogger.java
(line 72) GossipStage 0 13 0
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,698 StatusLogger.java
(line 72) AntiEntropyStage 0 0 0
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,698 StatusLogger.java
(line 72) MigrationStage 0 0 0
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,699 StatusLogger.java
(line 72) StreamStage 0 0 0
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,699 StatusLogger.java
(line 72) MemtablePostFlusher 0 0 0
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,699 StatusLogger.java
(line 72) FlushWriter 0 0 0
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,700 StatusLogger.java
(line 72) MiscStage 0 0 0
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,700 StatusLogger.java
(line 72) commitlog_archiver 0 0 0
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,700 StatusLogger.java
(line 72) InternalResponseStage 0 0 0
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,701 StatusLogger.java
(line 72) AntiEntropySessions 0 0 0
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,701 StatusLogger.java
(line 72) HintedHandoff 0 0 0
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,702 StatusLogger.java
(line 77) CompactionManager 2 4
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,702 StatusLogger.java
(line 89) MessagingService n/a 24,229
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,702 StatusLogger.java
(line 99) Cache Type Size Capacity KeysToSave
Provider
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,702 StatusLogger.java
(line 100) KeyCache 2184533 2184533 all
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,703 StatusLogger.java
(line 106) RowCache 52385581 52428800
all
org.apache.cassandra.cache.SerializingCacheProvider
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,703 StatusLogger.java
(line 113) ColumnFamily Memtable ops,data
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,703 StatusLogger.java
(line 116) system.NodeIdInfo 0,0
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,704 StatusLogger.java
(line 116) system.IndexInfo 0,0
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,705 StatusLogger.java
(line 116) system.LocationInfo 0,0
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,705 StatusLogger.java
(line 116) system.Versions 0,0
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,705 StatusLogger.java
(line 116) system.schema_keyspaces 0,0
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,705 StatusLogger.java
(line 116) system.Migrations 0,0
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,706 StatusLogger.java
(line 116) system.schema_columnfamilies 0,0
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,706 StatusLogger.java
(line 116) system.schema_columns 0,0
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,706 StatusLogger.java
(line 116) system.HintsColumnFamily 0,0
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,706 StatusLogger.java
(line 116) system.Schema 0,0
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,707 StatusLogger.java
(line 116) open.comp 0,0
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,707 StatusLogger.java
(line 116) open.bp 0,0
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,707 StatusLogger.java
(line 116) open.bn 312832,47184787
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,707 StatusLogger.java
(line 116) open.p 711,193201
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,707 StatusLogger.java
(line 116) open.bid 273064,46316018
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,708 StatusLogger.java
(line 116) open.rel 0,0
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,708 StatusLogger.java
(line 116) open.images 0,0
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,708 StatusLogger.java
(line 116) open.users 62287,86665510
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,708 StatusLogger.java
(line 116) open.sessions 4710,13153051
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,709 StatusLogger.java
(line 116) open.userIndices 4,1960
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,709 StatusLogger.java
(line 116) open.caches 50,4813457
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,709 StatusLogger.java
(line 116) open.content 0,0
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,710 StatusLogger.java
(line 116) open.enrich 30,20793
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,744 StatusLogger.java
(line 116) open.bt 1133,776831
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,863 StatusLogger.java
(line 116) open.alias 253,163933
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,864 StatusLogger.java
(line 116) open.bymsgid 249610,73075517
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,864 StatusLogger.java
(line 116) open.rank 319956,70898417
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,865 StatusLogger.java
(line 116) open.cmap 448,406193
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,865 StatusLogger.java
(line 116) open.pmap 659,566220
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,865 StatusLogger.java
(line 116) open.pict 50944,58659596
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,878 StatusLogger.java
(line 116) open.w 0,0
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,879 StatusLogger.java
(line 116) open.s 92395,46160381
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,879 StatusLogger.java
(line 116) open.bymrel 136607,57780555
INFO [ScheduledTasks:1] 2012-12-04 09:00:37,879 StatusLogger.java
(line 116) open.m 26720,51150067
It's appreciated,
Thanks,
-Mike
