[
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)
