There were no errors in the log (other than the messages dropped exception
pasted below), and the node does recover. We have only a small number of
secondary indexes (3 in the whole system).
However, I went through the cassandra code, and I believe I've worked through
this problem.
Just to finish out this thread, I realized that when you see:
INFO [ScheduledTasks:1] 2012-09-17 06:28:03,840 StatusLogger.java (line
72) FlushWriter 1 5 0
It is an issue. Cassandra will at various times enqueue many memtables for
flushing. By default, the queue size for this is 4. If more than 5 memtables
get queued for flushing (4 + 1 for the one currently being flushed), a lock
will be acquired and held across all tables until all memtables that need to be
flushed are enqueued. If it takes more than rpc_timeout_time_in_ms time to
flush enough information to allow all the pending memtables to be enqueued, a
"messages dropped" will occur. To put in other words, Cassandra will lock down
all tables until all pending flush requests fit in the pending queue. If your
queue size is 4, and 8 tables need to be flushed, Cassandra will lock down all
tables until a minimum of 3 memtables are flushed.
With this in mind, I went through the cassandra log and found this was indeed
the case looking at log entries similar to these:
INFO [OptionalTasks:1] 2012-09-16 05:54:29,750 ColumnFamilyStore.java (line
643) Enqueuing flush of Memtable-p@1525015234(18686281/341486464
serialized/live bytes, 29553 ops)
...
INFO [FlushWriter:29] 2012-09-16 05:54:29,768 Memtable.java (line 266) Writing
Memtable-p@1525015234(18686281/341486464 serialized/live bytes, 29553 ops)
...
INFO [FlushWriter:29] 2012-09-16 05:54:30,254 Memtable.java (line 307)
Completed flushing /data/cassandra/data/open/people/open-p-hd-441-Data.db
I was able to figure out what the rpc_timeout_in_ms needed to be to temporarily
prevent the problem.
We had plenty of write I/O available. We also had free memory. I increased
the memtable_flush_writers to "2" and memtable_flush_queue_size to "8". We
haven't had any timeouts for a number of days now.
Thanks for your help,
-Mike
On Sep 18, 2012, at 5:14 AM, aaron morton wrote:
> Any errors in the log ?
>
> The node recovers ?
>
> Do you use secondary indexes ? If so check comments for
> memtable_flush_queue_size in the yaml. if this value is too low writes may
> back up. But I would not expect it to cause dropped messages.
>
>> nodetool info also shows we have over a gig of available memory on the JVM
>> heap of each node.
>
> Not all memory is created equal :)
> ParNew is kicking in to GC the Eden space in the New Heap.
>
> It may just be that the node is getting hammered by something and IO is
> getting overwhelmed. If you can put the logs up someone might take a look.
>
> Cheers
>
> -----------------
> Aaron Morton
> Freelance Developer
> @aaronmorton
> http://www.thelastpickle.com
>
> On 18/09/2012, at 3:46 PM, Michael Theroux <mthero...@yahoo.com> wrote:
>
>> Thanks for the response.
>>
>> We are on version 1.1.2. We don't see the MutationStage back up. The dump
>> from the messages dropped error doesn't show a backup, but also watching
>> "nodetool tpstats" doesn't show any backup there.
>>
>> nodetool info also shows we have over a gig of available memory on the JVM
>> heap of each node.
>>
>> The earliest GCInspector traces I see before one of the more recent
>> incidents in which messages were dropped are:
>>
>> INFO [ScheduledTasks:1] 2012-09-18 02:25:53,928 GCInspector.java (line
>> 122) GC for ParNew: 396 ms for 1 collections, 2064505088 used; max is
>> 4253024256
>>
>> NFO [ScheduledTasks:1] 2012-09-18 02:25:55,929 GCInspector.java (line
>> 122) GC for ParNew: 485 ms for 1 collections, 1961875064 used; max is
>> 4253024256
>>
>> INFO [ScheduledTasks:1] 2012-09-18 02:25:57,930 GCInspector.java (line
>> 122) GC for ParNew: 265 ms for 1 collections, 1968074096 used; max is
>> 4253024256
>>
>> But this was 45 minutes before messages were dropped.
>>
>> It's appreciated,
>> -Mike
>>
>> On Sep 17, 2012, at 11:27 PM, aaron morton wrote:
>>
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,839 StatusLogger.java (line
>>>> 72) MemtablePostFlusher 1 5 0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,840 StatusLogger.java (line
>>>> 72) FlushWriter 1 5 0
>>> Looks suspiciously like
>>> http://mail-archives.apache.org/mod_mbox/cassandra-user/201209.mbox/%3c9fb0e801-b1ed-41c4-9939-bafbddf15...@thelastpickle.com%3E
>>>
>>> What version are you on ?
>>>
>>> Are there any ERROR log messages before this ?
>>>
>>> Are you seeing MutationStage back up ?
>>>
>>> Are you see log messages from GCInspector ?
>>>
>>> Cheers
>>>
>>> -----------------
>>> Aaron Morton
>>> Freelance Developer
>>> @aaronmorton
>>> http://www.thelastpickle.com
>>>
>>> On 18/09/2012, at 2:16 AM, Michael Theroux <mthero...@yahoo.com> wrote:
>>>
>>>> Hello,
>>>>
>>>> While under load, we have occasionally been seeing "messages dropped"
>>>> errors in our cassandra log. Doing some research, I understand this is
>>>> part of Cassandra's design to shed load, and we should look at the
>>>> tpstats-like output to determine what should be done to resolve the
>>>> situation. Typically, you will see lots of messages blocked or pending,
>>>> and that might be an indicator that a specific part of hardware needs to
>>>> be improved/tuned/upgraded.
>>>>
>>>> However, looking at the output we are getting, I'm finding it difficult to
>>>> see what needs to be tuned, as it looks to me cassandra is handling the
>>>> load within the mutation stage:
>>>>
>>>> NFO [ScheduledTasks:1] 2012-09-17 06:28:03,266 MessagingService.java (line
>>>> 658) 119 MUTATION messages dropped in last 5000ms
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,645 StatusLogger.java (line
>>>> 57) Pool Name Active Pending Blocked
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,836 StatusLogger.java (line
>>>> 72) ReadStage 3 3 0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,837 StatusLogger.java (line
>>>> 72) RequestResponseStage 0 0 0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,837 StatusLogger.java (line
>>>> 72) ReadRepairStage 0 0 0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,837 StatusLogger.java (line
>>>> 72) MutationStage 0 0 0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,838 StatusLogger.java (line
>>>> 72) ReplicateOnWriteStage 0 0 0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,838 StatusLogger.java (line
>>>> 72) GossipStage 0 0 0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,839 StatusLogger.java (line
>>>> 72) AntiEntropyStage 0 0 0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,839 StatusLogger.java (line
>>>> 72) MigrationStage 0 0 0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,839 StatusLogger.java (line
>>>> 72) StreamStage 0 0 0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,839 StatusLogger.java (line
>>>> 72) MemtablePostFlusher 1 5 0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,840 StatusLogger.java (line
>>>> 72) FlushWriter 1 5 0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,840 StatusLogger.java (line
>>>> 72) MiscStage 0 0 0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,840 StatusLogger.java (line
>>>> 72) commitlog_archiver 0 0 0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,841 StatusLogger.java (line
>>>> 72) InternalResponseStage 0 0 0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,841 StatusLogger.java (line
>>>> 72) AntiEntropySessions 0 0 0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,851 StatusLogger.java (line
>>>> 72) HintedHandoff 0 0 0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,851 StatusLogger.java (line
>>>> 77) CompactionManager 0 0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,852 StatusLogger.java (line
>>>> 89) MessagingService n/a 0,0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,852 StatusLogger.java (line
>>>> 99) Cache Type Size Capacity
>>>> KeysToSave
>>>> Provider
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,853 StatusLogger.java (line
>>>> 100) KeyCache 2184533 2184533
>>>> all
>>>>
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,853 StatusLogger.java (line
>>>> 106) RowCache 0 0
>>>> all
>>>> org.apache.cassandra.cache.SerializingCacheProvider
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,853 StatusLogger.java (line
>>>> 113) ColumnFamily Memtable ops,data
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,853 StatusLogger.java (line
>>>> 116) system.NodeIdInfo 0,0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,854 StatusLogger.java (line
>>>> 116) system.IndexInfo 0,0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,854 StatusLogger.java (line
>>>> 116) system.LocationInfo 0,0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,854 StatusLogger.java (line
>>>> 116) system.Versions 0,0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,855 StatusLogger.java (line
>>>> 116) system.schema_keyspaces 0,0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,855 StatusLogger.java (line
>>>> 116) system.Migrations 0,0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,855 StatusLogger.java (line
>>>> 116) system.schema_columnfamilies 0,0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,856 StatusLogger.java (line
>>>> 116) system.schema_columns 0,0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,856 StatusLogger.java (line
>>>> 116) system.HintsColumnFamily 0,0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,856 StatusLogger.java (line
>>>> 116) system.Schema 0,0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,857 StatusLogger.java (line
>>>> 116) prod.comp 0,0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,857 StatusLogger.java (line
>>>> 116) prod.byp 224,61863
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,857 StatusLogger.java (line
>>>> 116) prod.byn 30,6106
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,857 StatusLogger.java (line
>>>> 116) prod.p 3354,3792954
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,858 StatusLogger.java (line
>>>> 116) prod.rel 788,153294
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,858 StatusLogger.java (line
>>>> 116) prod.i 46,271517
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,859 StatusLogger.java (line
>>>> 116) prod.users 18489,5650405
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,859 StatusLogger.java (line
>>>> 116) prod.caches 40,7512998
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,859 StatusLogger.java (line
>>>> 116) prod.sessions 8085,13063121
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,859 StatusLogger.java (line
>>>> 116) prod.content 0,0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,860 StatusLogger.java (line
>>>> 116) prod.enr 436,341190
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,860 StatusLogger.java (line
>>>> 116) prod.byt 23800,9880339
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,861 StatusLogger.java (line
>>>> 116) prod.aliases 63603,10475769
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,861 StatusLogger.java (line
>>>> 116) prod.ran 1500,329387
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,861 StatusLogger.java (line
>>>> 116) prod.cmap 0,0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,861 StatusLogger.java (line
>>>> 116) prod.pmap 73032,61237450
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,862 StatusLogger.java (line
>>>> 116) prod.pic 5421,4438066
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,862 StatusLogger.java (line
>>>> 116) prod.watchdog 0,0
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,863 StatusLogger.java (line
>>>> 116) prod.s 31,40924
>>>> INFO [ScheduledTasks:1] 2012-09-17 06:28:03,863 StatusLogger.java (line
>>>> 116) prod.m 21690,64262284
>>>>
>>>>
>>>> We are using a write consistency level of LOCAL_QUROUM over a six node
>>>> cluster. Any observations are welcome,
>>>>
>>>> Thanks,
>>>> -Mike
>>>
>>
>
