[ https://issues.apache.org/jira/browse/CASSANDRA-6187?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Li Zou updated CASSANDRA-6187: ------------------------------ Description: Under normal operation condition without any interruption, the traffic generator will periodically see a couple of seconds of zero (or very little) transactions, i.e. the throughput can be quite high for a while, then comes down to zero (or very little) transactions for 10 ~ 20 seconds. The Cassandra system log occasionally also logs message drops. But these message drop events do not correlate in time to the observed transaction drop events. Example of message dropping log: {noformat} INFO [ScheduledTasks:1] 2013-10-11 16:36:12,216 MessagingService.java (line 812) 1191 MUTATION messages dropped in last 5000ms INFO [ScheduledTasks:1] 2013-10-11 16:36:12,217 MessagingService.java (line 812) 502 READ_REPAIR messages dropped in last 5000ms INFO [ScheduledTasks:1] 2013-10-11 16:36:12,217 StatusLogger.java (line 55) Pool Name Active Pending Completed Blocked All Time Blocked INFO [ScheduledTasks:1] 2013-10-11 16:36:12,246 StatusLogger.java (line 70) ReadStage 0 0 845326 0 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,246 StatusLogger.java (line 70) RequestResponseStage 0 0 1643358 0 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,246 StatusLogger.java (line 70) ReadRepairStage 0 0 61247 0 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,247 StatusLogger.java (line 70) MutationStage 0 0 1155502 0 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,247 StatusLogger.java (line 70) ReplicateOnWriteStage 0 0 0 0 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,247 StatusLogger.java (line 70) GossipStage 0 0 5391 0 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,248 StatusLogger.java (line 70) AntiEntropyStage 0 0 0 0 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,248 StatusLogger.java (line 70) MigrationStage 0 0 14 0 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,248 StatusLogger.java (line 70) MemtablePostFlusher 0 0 99 0 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,248 StatusLogger.java (line 70) MemoryMeter 0 0 58 0 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,249 StatusLogger.java (line 70) FlushWriter 0 0 45 0 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,249 StatusLogger.java (line 70) MiscStage 0 0 0 0 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,249 StatusLogger.java (line 70) commitlog_archiver 0 0 0 0 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,250 StatusLogger.java (line 70) InternalResponseStage 0 0 3 0 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,250 StatusLogger.java (line 70) HintedHandoff 0 0 7 0 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,250 StatusLogger.java (line 79) CompactionManager 0 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,250 StatusLogger.java (line 81) Commitlog n/a 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,251 StatusLogger.java (line 93) MessagingService n/a 0,0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,251 StatusLogger.java (line 103) Cache Type Size Capacity KeysToSave INFO [ScheduledTasks:1] 2013-10-11 16:36:12,251 StatusLogger.java (line 105) KeyCache 74140 104857600 all INFO [ScheduledTasks:1] 2013-10-11 16:36:12,251 StatusLogger.java (line 111) RowCache 0 0 all INFO [ScheduledTasks:1] 2013-10-11 16:36:12,251 StatusLogger.java (line 118) ColumnFamily Memtable ops,data INFO [ScheduledTasks:1] 2013-10-11 16:36:12,251 StatusLogger.java (line 121) system.schema_triggers 0,0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,252 StatusLogger.java (line 121) system.local 18,520 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,252 StatusLogger.java (line 121) system.peers 14,1560 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,252 StatusLogger.java (line 121) system.batchlog 0,0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,252 StatusLogger.java (line 121) system.NodeIdInfo 0,0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,252 StatusLogger.java (line 121) system.compactions_in_progress 0,0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,252 StatusLogger.java (line 121) system.schema_keyspaces 0,0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,253 StatusLogger.java (line 121) system.compaction_history 0,0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,253 StatusLogger.java (line 121) system.paxos 0,0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,253 StatusLogger.java (line 121) system.schema_columns 0,0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,253 StatusLogger.java (line 121) system.schema_columnfamilies 0,0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,253 StatusLogger.java (line 121) system.IndexInfo 0,0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,253 StatusLogger.java (line 121) system.range_xfers 0,0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,253 StatusLogger.java (line 121) system.peer_events 0,0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,254 StatusLogger.java (line 121) system.hints 0,0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,254 StatusLogger.java (line 121) system.sstable_activity 25,3600 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,254 StatusLogger.java (line 121) my.idx_oh 0,0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,254 StatusLogger.java (line 121) my.a_session 42183,11257646 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,254 StatusLogger.java (line 121) my.i_session_cf 823386,258634249 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,254 StatusLogger.java (line 121) my.p_session 325310,93987539 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,254 StatusLogger.java (line 121) system_traces.sessions 0,0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,255 StatusLogger.java (line 121) system_traces.events 0,0 INFO [MemoryMeter:1] 2013-10-11 17:11:29,058 Memtable.java (line 444) CFS(Keyspace='system', ColumnFamily='sstable_activity') liveRatio is 14.653968253968253 (just-counted was 14.653968253968253). c alculation took 0ms for 21 columns {noformat} was: Under normal operation condition without any interruption, the traffic generator will periodically see a couple of seconds of zero (or very little) transactions, i.e. the throughput can be quite high for a while, then comes down to zero (or very little) transactions for 10 ~ 20 seconds. The Cassandra system log occasionally also logs message drops. But these message drop events do not correlate in time to the observed transaction drop events. Example of message dropping log: {noformat} INFO [ScheduledTasks:1] 2013-10-11 16:36:12,216 MessagingService.java (line 812) 1191 MUTATION messages dropped in last 5000ms INFO [ScheduledTasks:1] 2013-10-11 16:36:12,217 MessagingService.java (line 812) 502 READ_REPAIR messages dropped in last 5000ms INFO [ScheduledTasks:1] 2013-10-11 16:36:12,217 StatusLogger.java (line 55) Pool Name Active Pending Completed Blocked All Time Blocked INFO [ScheduledTasks:1] 2013-10-11 16:36:12,246 StatusLogger.java (line 70) ReadStage 0 0 845326 0 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,246 StatusLogger.java (line 70) RequestResponseStage 0 0 1643358 0 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,246 StatusLogger.java (line 70) ReadRepairStage 0 0 61247 0 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,247 StatusLogger.java (line 70) MutationStage 0 0 1155502 0 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,247 StatusLogger.java (line 70) ReplicateOnWriteStage 0 0 0 0 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,247 StatusLogger.java (line 70) GossipStage 0 0 5391 0 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,248 StatusLogger.java (line 70) AntiEntropyStage 0 0 0 0 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,248 StatusLogger.java (line 70) MigrationStage 0 0 14 0 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,248 StatusLogger.java (line 70) MemtablePostFlusher 0 0 99 0 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,248 StatusLogger.java (line 70) MemoryMeter 0 0 58 0 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,249 StatusLogger.java (line 70) FlushWriter 0 0 45 0 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,249 StatusLogger.java (line 70) MiscStage 0 0 0 0 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,249 StatusLogger.java (line 70) commitlog_archiver 0 0 0 0 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,250 StatusLogger.java (line 70) InternalResponseStage 0 0 3 0 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,250 StatusLogger.java (line 70) HintedHandoff 0 0 7 0 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,250 StatusLogger.java (line 79) CompactionManager 0 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,250 StatusLogger.java (line 81) Commitlog n/a 0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,251 StatusLogger.java (line 93) MessagingService n/a 0,0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,251 StatusLogger.java (line 103) Cache Type Size Capacity KeysToSave INFO [ScheduledTasks:1] 2013-10-11 16:36:12,251 StatusLogger.java (line 105) KeyCache 74140 104857600 all INFO [ScheduledTasks:1] 2013-10-11 16:36:12,251 StatusLogger.java (line 111) RowCache 0 0 all INFO [ScheduledTasks:1] 2013-10-11 16:36:12,251 StatusLogger.java (line 118) ColumnFamily Memtable ops,data INFO [ScheduledTasks:1] 2013-10-11 16:36:12,251 StatusLogger.java (line 121) system.schema_triggers 0,0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,252 StatusLogger.java (line 121) system.local 18,520 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,252 StatusLogger.java (line 121) system.peers 14,1560 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,252 StatusLogger.java (line 121) system.batchlog 0,0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,252 StatusLogger.java (line 121) system.NodeIdInfo 0,0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,252 StatusLogger.java (line 121) system.compactions_in_progress 0,0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,252 StatusLogger.java (line 121) system.schema_keyspaces 0,0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,253 StatusLogger.java (line 121) system.compaction_history 0,0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,253 StatusLogger.java (line 121) system.paxos 0,0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,253 StatusLogger.java (line 121) system.schema_columns 0,0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,253 StatusLogger.java (line 121) system.schema_columnfamilies 0,0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,253 StatusLogger.java (line 121) system.IndexInfo 0,0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,253 StatusLogger.java (line 121) system.range_xfers 0,0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,253 StatusLogger.java (line 121) system.peer_events 0,0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,254 StatusLogger.java (line 121) system.hints 0,0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,254 StatusLogger.java (line 121) system.sstable_activity 25,3600 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,254 StatusLogger.java (line 121) pcrf.idx_origin_host 0,0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,254 StatusLogger.java (line 121) pcrf.af_session 42183,11257646 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,254 StatusLogger.java (line 121) pcrf.ip_session_cf 823386,258634249 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,254 StatusLogger.java (line 121) pcrf.pcef_session 325310,93987539 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,254 StatusLogger.java (line 121) system_traces.sessions 0,0 INFO [ScheduledTasks:1] 2013-10-11 16:36:12,255 StatusLogger.java (line 121) system_traces.events 0,0 INFO [MemoryMeter:1] 2013-10-11 17:11:29,058 Memtable.java (line 444) CFS(Keyspace='system', ColumnFamily='sstable_activity') liveRatio is 14.653968253968253 (just-counted was 14.653968253968253). c alculation took 0ms for 21 columns {noformat} > Cassandra-2.0 node seems to be pausing periodically under normal operations > --------------------------------------------------------------------------- > > Key: CASSANDRA-6187 > URL: https://issues.apache.org/jira/browse/CASSANDRA-6187 > Project: Cassandra > Issue Type: Bug > Components: Core > Environment: One data center of 4 Cassandra-2.0 nodes with default > configuration parameters deployed on 4 separate machines. > A testing app (with either Astyanax or DataStax client driver) interacts with > the Cassandra data center. > A traffic generator is sending traffic to the testing app for testing purpose. > Reporter: Li Zou > > Under normal operation condition without any interruption, the traffic > generator will periodically see a couple of seconds of zero (or very little) > transactions, i.e. the throughput can be quite high for a while, then comes > down to zero (or very little) transactions for 10 ~ 20 seconds. > The Cassandra system log occasionally also logs message drops. But these > message drop events do not correlate in time to the observed transaction drop > events. > Example of message dropping log: > {noformat} > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,216 MessagingService.java (line > 812) 1191 MUTATION messages dropped in last 5000ms > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,217 MessagingService.java (line > 812) 502 READ_REPAIR messages dropped in last 5000ms > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,217 StatusLogger.java (line 55) > Pool Name Active Pending Completed Blocked All > Time Blocked > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,246 StatusLogger.java (line 70) > ReadStage 0 0 845326 0 > 0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,246 StatusLogger.java (line 70) > RequestResponseStage 0 0 1643358 0 > 0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,246 StatusLogger.java (line 70) > ReadRepairStage 0 0 61247 0 > 0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,247 StatusLogger.java (line 70) > MutationStage 0 0 1155502 0 > 0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,247 StatusLogger.java (line 70) > ReplicateOnWriteStage 0 0 0 0 > 0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,247 StatusLogger.java (line 70) > GossipStage 0 0 5391 0 > 0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,248 StatusLogger.java (line 70) > AntiEntropyStage 0 0 0 0 > 0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,248 StatusLogger.java (line 70) > MigrationStage 0 0 14 0 > 0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,248 StatusLogger.java (line 70) > MemtablePostFlusher 0 0 99 0 > 0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,248 StatusLogger.java (line 70) > MemoryMeter 0 0 58 0 > 0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,249 StatusLogger.java (line 70) > FlushWriter 0 0 45 0 > 0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,249 StatusLogger.java (line 70) > MiscStage 0 0 0 0 > 0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,249 StatusLogger.java (line 70) > commitlog_archiver 0 0 0 0 > 0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,250 StatusLogger.java (line 70) > InternalResponseStage 0 0 3 0 > 0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,250 StatusLogger.java (line 70) > HintedHandoff 0 0 7 0 > 0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,250 StatusLogger.java (line 79) > CompactionManager 0 0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,250 StatusLogger.java (line 81) > Commitlog n/a 0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,251 StatusLogger.java (line 93) > MessagingService n/a 0,0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,251 StatusLogger.java (line 103) > Cache Type Size Capacity > KeysToSave > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,251 StatusLogger.java (line 105) > KeyCache 74140 104857600 > all > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,251 StatusLogger.java (line 111) > RowCache 0 0 > all > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,251 StatusLogger.java (line 118) > ColumnFamily Memtable ops,data > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,251 StatusLogger.java (line 121) > system.schema_triggers 0,0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,252 StatusLogger.java (line 121) > system.local 18,520 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,252 StatusLogger.java (line 121) > system.peers 14,1560 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,252 StatusLogger.java (line 121) > system.batchlog 0,0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,252 StatusLogger.java (line 121) > system.NodeIdInfo 0,0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,252 StatusLogger.java (line 121) > system.compactions_in_progress 0,0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,252 StatusLogger.java (line 121) > system.schema_keyspaces 0,0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,253 StatusLogger.java (line 121) > system.compaction_history 0,0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,253 StatusLogger.java (line 121) > system.paxos 0,0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,253 StatusLogger.java (line 121) > system.schema_columns 0,0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,253 StatusLogger.java (line 121) > system.schema_columnfamilies 0,0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,253 StatusLogger.java (line 121) > system.IndexInfo 0,0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,253 StatusLogger.java (line 121) > system.range_xfers 0,0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,253 StatusLogger.java (line 121) > system.peer_events 0,0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,254 StatusLogger.java (line 121) > system.hints 0,0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,254 StatusLogger.java (line 121) > system.sstable_activity 25,3600 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,254 StatusLogger.java (line 121) > my.idx_oh 0,0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,254 StatusLogger.java (line 121) > my.a_session 42183,11257646 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,254 StatusLogger.java (line 121) > my.i_session_cf 823386,258634249 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,254 StatusLogger.java (line 121) > my.p_session 325310,93987539 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,254 StatusLogger.java (line 121) > system_traces.sessions 0,0 > INFO [ScheduledTasks:1] 2013-10-11 16:36:12,255 StatusLogger.java (line 121) > system_traces.events 0,0 > INFO [MemoryMeter:1] 2013-10-11 17:11:29,058 Memtable.java (line 444) > CFS(Keyspace='system', ColumnFamily='sstable_activity') liveRatio is > 14.653968253968253 (just-counted was 14.653968253968253). c > alculation took 0ms for 21 columns > {noformat} -- This message was sent by Atlassian JIRA (v6.1#6144)