You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@cassandra.apache.org by "Li Zou (JIRA)" <ji...@apache.org> on 2013/11/06 23:18:18 UTC
[jira] [Updated] (CASSANDRA-6187) Cassandra-2.0 node seems to be
pausing periodically under normal operations
[ 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)