You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@cassandra.apache.org by Marco Gasparini <ma...@competitoor.com> on 2019/03/08 08:27:16 UTC
too many logDroppedMessages and StatusLogger
Hi all,
I cannot understand why I get the following logs, they appear every day at
not fixed period of time. I saw them every 2 minutes or every 10 seconds, I
cannot find any pattern.
I took this very example here during an heavy workload of writes and reads
but I get them also during a very little workload and without any active
compaction/repair/streaming process and no high cpu/memory/iowait usage.
2019-03-08 01:49:47,868 INFO [ScheduledTasks:1] MessagingService.java:1246
> logDroppedMessages READ messages were dropped in last 5000 ms: 0 internal
> and 1 cross node. Mean internal dropped latency: 6357 ms and Mean
> cross-node dropped latency: 6556 ms
> 2019-03-08 01:49:47,868 INFO [ScheduledTasks:1] StatusLogger.java:47 log
> Pool Name Active Pending Completed Blocked All
> Time Blocked
> 2019-03-08 01:49:47,870 INFO [ScheduledTasks:1] StatusLogger.java:51 log
> MutationStage 0 0 17641121 0
> 0
> 2019-03-08 01:49:47,870 INFO [ScheduledTasks:1] StatusLogger.java:51 log
> ViewMutationStage 0 0 0 0
> 0
> 2019-03-08 01:49:47,870 INFO [ScheduledTasks:1] StatusLogger.java:51 log
> ReadStage 0 0 6851090 0
> 0
> 2019-03-08 01:49:47,870 INFO [ScheduledTasks:1] StatusLogger.java:51 log
> RequestResponseStage 0 0 13646587 0
> 0
> 2019-03-08 01:49:47,870 INFO [ScheduledTasks:1] StatusLogger.java:51 log
> ReadRepairStage 0 0 352884 0
> 0
> 2019-03-08 01:49:47,870 INFO [ScheduledTasks:1] StatusLogger.java:51 log
> CounterMutationStage 0 0 0 0
> 0
> 2019-03-08 01:49:47,870 INFO [ScheduledTasks:1] StatusLogger.java:51 log
> MiscStage 0 0 0 0
> 0
> 2019-03-08 01:49:47,870 INFO [ScheduledTasks:1] StatusLogger.java:51 log
> CompactionExecutor 0 0 882478 0
> 0
> 2019-03-08 01:49:47,871 INFO [ScheduledTasks:1] StatusLogger.java:51 log
> MemtableReclaimMemory 0 0 4101 0
> 0
> 2019-03-08 01:49:47,871 INFO [ScheduledTasks:1] StatusLogger.java:51 log
> PendingRangeCalculator 0 0 7 0
> 0
> 2019-03-08 01:49:47,871 INFO [ScheduledTasks:1] StatusLogger.java:51 log
> GossipStage 0 0 4399705 0
> 0
> 2019-03-08 01:49:47,871 INFO [ScheduledTasks:1] StatusLogger.java:51 log
> SecondaryIndexManagement 0 0 0 0
> 0
> 2019-03-08 01:49:47,871 INFO [ScheduledTasks:1] StatusLogger.java:51 log
> HintsDispatcher 0 0 2165 0
> 0
> 2019-03-08 01:49:47,871 INFO [ScheduledTasks:1] StatusLogger.java:51 log
> MigrationStage 0 0 50 0
> 0
> 2019-03-08 01:49:47,871 INFO [ScheduledTasks:1] StatusLogger.java:51 log
> MemtablePostFlush 0 0 4393 0
> 0
> 2019-03-08 01:49:47,872 INFO [ScheduledTasks:1] StatusLogger.java:51 log
> PerDiskMemtableFlushWriter_0 0 0 4097 0
> 0
> 2019-03-08 01:49:47,872 INFO [ScheduledTasks:1] StatusLogger.java:51 log
> ValidationExecutor 0 0 1565 0
> 0
> 2019-03-08 01:49:47,872 INFO [ScheduledTasks:1] StatusLogger.java:51 log
> Sampler 0 0 0 0
> 0
> 2019-03-08 01:49:47,872 INFO [ScheduledTasks:1] StatusLogger.java:51 log
> MemtableFlushWriter 0 0 4101 0
> 0
> 2019-03-08 01:49:47,872 INFO [ScheduledTasks:1] StatusLogger.java:51 log
> InternalResponseStage 0 0 121813 0
> 0
> 2019-03-08 01:49:47,872 INFO [ScheduledTasks:1] StatusLogger.java:51 log
> AntiEntropyStage 0 0 6997 0
> 0
> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:51 log
> CacheCleanupExecutor 0 0 33 0
> 0
> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:51 log
> Native-Transport-Requests 4 0 364526951 0
> 0
> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:61 log
> CompactionManager 0 0
> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:73 log
> MessagingService n/a 2/0
> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:83 log
> Cache Type Size Capacity
> KeysToSave
> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:85 log
> KeyCache 104856992 104857600
> all
> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:91 log
> RowCache 0 0
> all
> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:98 log
> Table Memtable ops,data
> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system_distributed.parent_repair_history 0,0
> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system_distributed.repair_history 0,0
> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system_distributed.view_build_status 0,0
> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system.compaction_history 3,781
> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system.schema_aggregates 0,0
> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system.schema_triggers 0,0
> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system.size_estimates 2535,100788
> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system.paxos 0,0
> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system.views_builds_in_progress 0,0
> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system.batches 0,0
> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system.schema_keyspaces 0,0
> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system.sstable_activity 129,3974
> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system.batchlog 0,0
> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system.schema_columns 0,0
> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system.hints 0,0
> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system.IndexInfo 0,0
> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system.schema_columnfamilies 0,0
> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system.schema_functions 0,0
> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system.built_views 0,0
> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system.peer_events 0,0
> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system.range_xfers 0,0
> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system.peers 0,0
> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system.transferred_ranges 0,0
> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system.schema_usertypes 0,0
> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system.local 0,0
> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system.available_ranges 0,0
> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system.prepared_statements 0,0
> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system_schema.columns 0,0
> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system_schema.types 0,0
> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system_schema.indexes 0,0
> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system_schema.keyspaces 0,0
> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system_schema.dropped_columns 0,0
> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system_schema.aggregates 0,0
> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system_schema.triggers 0,0
> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system_schema.tables 0,0
> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system_schema.views 0,0
> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system_schema.functions 0,0
> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> web_history.web_pages_history 2851,402270519
> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> _kibana.doc 0,0
> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> scratchboard.job_ids_scratches 156810,13026241
> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> elastic_admin.metadata 0,0
> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system_auth.roles 0,0
> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system_auth.role_members 0,0
> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system_auth.resource_role_permissons_index 0,0
> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system_auth.role_permissions 0,0
> 2019-03-08 01:49:47,876 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system_traces.sessions 0,0
> 2019-03-08 01:49:47,876 INFO [ScheduledTasks:1] StatusLogger.java:101 log
> system_traces.events 0,0
I have a 5 nodes cluster running Cassandra 3.11.3.5. During high workload I
got 500k reads and about 1M writes (inserts and/or deletes) in about 2.5
hours, after that the workload goes down.
any help is very appreciate.
Regards
Marco
Re: too many logDroppedMessages and StatusLogger
Posted by Marco Gasparini <ma...@competitoor.com>.
thanks for the answer Nate,
my queries are more like the following:
select f1,f2,f3, bigtxt from mytable where f1= ? and f2= ? limit 10;
insert into mytable (f1,f2,f3,bigtxt) values (?,?,?,?)
actually I have a text field (bigtxt) that could be > 1MB.
Marco
Il giorno lun 11 mar 2019 alle ore 22:21 Nate McCall <zz...@gmail.com>
ha scritto:
> Are you using queries with a large number of arguments to an IN clause
> on a partition key? If so, the coordinator has to:
> - hold open the client request
> - unwind the IN clause into individual statements
> - scatter/gathering those statements around the cluster (each at the
> requested consistency level!)
> - pull it all back together and send it out
>
> In extreme cases, this can flood internode messaging and make things
> look slow even when the system is near idle.
>
> On Fri, Mar 8, 2019 at 9:27 PM Marco Gasparini
> <ma...@competitoor.com> wrote:
> >
> > Hi all,
> >
> > I cannot understand why I get the following logs, they appear every day
> at not fixed period of time. I saw them every 2 minutes or every 10
> seconds, I cannot find any pattern.
> > I took this very example here during an heavy workload of writes and
> reads but I get them also during a very little workload and without any
> active compaction/repair/streaming process and no high cpu/memory/iowait
> usage.
> >
> >> 2019-03-08 01:49:47,868 INFO [ScheduledTasks:1]
> MessagingService.java:1246 logDroppedMessages READ messages were dropped in
> last 5000 ms: 0 internal and 1 cross node. Mean internal dropped latency:
> 6357 ms and Mean cross-node dropped latency: 6556 ms
> >> 2019-03-08 01:49:47,868 INFO [ScheduledTasks:1] StatusLogger.java:47
> log Pool Name Active Pending Completed Blocked
> All Time Blocked
> >> 2019-03-08 01:49:47,870 INFO [ScheduledTasks:1] StatusLogger.java:51
> log MutationStage 0 0 17641121 0
> 0
> >> 2019-03-08 01:49:47,870 INFO [ScheduledTasks:1] StatusLogger.java:51
> log ViewMutationStage 0 0 0 0
> 0
> >> 2019-03-08 01:49:47,870 INFO [ScheduledTasks:1] StatusLogger.java:51
> log ReadStage 0 0 6851090 0
> 0
> >> 2019-03-08 01:49:47,870 INFO [ScheduledTasks:1] StatusLogger.java:51
> log RequestResponseStage 0 0 13646587 0
> 0
> >> 2019-03-08 01:49:47,870 INFO [ScheduledTasks:1] StatusLogger.java:51
> log ReadRepairStage 0 0 352884 0
> 0
> >> 2019-03-08 01:49:47,870 INFO [ScheduledTasks:1] StatusLogger.java:51
> log CounterMutationStage 0 0 0 0
> 0
> >> 2019-03-08 01:49:47,870 INFO [ScheduledTasks:1] StatusLogger.java:51
> log MiscStage 0 0 0 0
> 0
> >> 2019-03-08 01:49:47,870 INFO [ScheduledTasks:1] StatusLogger.java:51
> log CompactionExecutor 0 0 882478 0
> 0
> >> 2019-03-08 01:49:47,871 INFO [ScheduledTasks:1] StatusLogger.java:51
> log MemtableReclaimMemory 0 0 4101 0
> 0
> >> 2019-03-08 01:49:47,871 INFO [ScheduledTasks:1] StatusLogger.java:51
> log PendingRangeCalculator 0 0 7 0
> 0
> >> 2019-03-08 01:49:47,871 INFO [ScheduledTasks:1] StatusLogger.java:51
> log GossipStage 0 0 4399705 0
> 0
> >> 2019-03-08 01:49:47,871 INFO [ScheduledTasks:1] StatusLogger.java:51
> log SecondaryIndexManagement 0 0 0 0
> 0
> >> 2019-03-08 01:49:47,871 INFO [ScheduledTasks:1] StatusLogger.java:51
> log HintsDispatcher 0 0 2165 0
> 0
> >> 2019-03-08 01:49:47,871 INFO [ScheduledTasks:1] StatusLogger.java:51
> log MigrationStage 0 0 50 0
> 0
> >> 2019-03-08 01:49:47,871 INFO [ScheduledTasks:1] StatusLogger.java:51
> log MemtablePostFlush 0 0 4393 0
> 0
> >> 2019-03-08 01:49:47,872 INFO [ScheduledTasks:1] StatusLogger.java:51
> log PerDiskMemtableFlushWriter_0 0 0 4097
> 0 0
> >> 2019-03-08 01:49:47,872 INFO [ScheduledTasks:1] StatusLogger.java:51
> log ValidationExecutor 0 0 1565 0
> 0
> >> 2019-03-08 01:49:47,872 INFO [ScheduledTasks:1] StatusLogger.java:51
> log Sampler 0 0 0 0
> 0
> >> 2019-03-08 01:49:47,872 INFO [ScheduledTasks:1] StatusLogger.java:51
> log MemtableFlushWriter 0 0 4101 0
> 0
> >> 2019-03-08 01:49:47,872 INFO [ScheduledTasks:1] StatusLogger.java:51
> log InternalResponseStage 0 0 121813 0
> 0
> >> 2019-03-08 01:49:47,872 INFO [ScheduledTasks:1] StatusLogger.java:51
> log AntiEntropyStage 0 0 6997 0
> 0
> >> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:51
> log CacheCleanupExecutor 0 0 33 0
> 0
> >> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:51
> log Native-Transport-Requests 4 0 364526951 0
> 0
> >> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:61
> log CompactionManager 0 0
> >> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:73
> log MessagingService n/a 2/0
> >> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:83
> log Cache Type Size Capacity
> KeysToSave
> >> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:85
> log KeyCache 104856992 104857600
> all
> >> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:91
> log RowCache 0 0
> all
> >> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:98
> log Table Memtable ops,data
> >> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system_distributed.parent_repair_history 0,0
> >> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system_distributed.repair_history 0,0
> >> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system_distributed.view_build_status 0,0
> >> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system.compaction_history 3,781
> >> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system.schema_aggregates 0,0
> >> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system.schema_triggers 0,0
> >> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system.size_estimates 2535,100788
> >> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system.paxos 0,0
> >> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system.views_builds_in_progress 0,0
> >> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system.batches 0,0
> >> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system.schema_keyspaces 0,0
> >> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system.sstable_activity 129,3974
> >> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system.batchlog 0,0
> >> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system.schema_columns 0,0
> >> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system.hints 0,0
> >> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system.IndexInfo 0,0
> >> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system.schema_columnfamilies 0,0
> >> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system.schema_functions 0,0
> >> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system.built_views 0,0
> >> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system.peer_events 0,0
> >> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system.range_xfers 0,0
> >> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system.peers 0,0
> >> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system.transferred_ranges 0,0
> >> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system.schema_usertypes 0,0
> >> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system.local 0,0
> >> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system.available_ranges 0,0
> >> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system.prepared_statements 0,0
> >> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system_schema.columns 0,0
> >> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system_schema.types 0,0
> >> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system_schema.indexes 0,0
> >> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system_schema.keyspaces 0,0
> >> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system_schema.dropped_columns 0,0
> >> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system_schema.aggregates 0,0
> >> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system_schema.triggers 0,0
> >> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system_schema.tables 0,0
> >> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system_schema.views 0,0
> >> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system_schema.functions 0,0
> >> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101
> log web_history.web_pages_history 2851,402270519
> >> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101
> log _kibana.doc 0,0
> >> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101
> log scratchboard.job_ids_scratches 156810,13026241
> >> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101
> log elastic_admin.metadata 0,0
> >> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system_auth.roles 0,0
> >> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system_auth.role_members 0,0
> >> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system_auth.resource_role_permissons_index 0,0
> >> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system_auth.role_permissions 0,0
> >> 2019-03-08 01:49:47,876 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system_traces.sessions 0,0
> >> 2019-03-08 01:49:47,876 INFO [ScheduledTasks:1] StatusLogger.java:101
> log system_traces.events 0,0
> >
> >
> > I have a 5 nodes cluster running Cassandra 3.11.3.5. During high
> workload I got 500k reads and about 1M writes (inserts and/or deletes) in
> about 2.5 hours, after that the workload goes down.
> >
> > any help is very appreciate.
> >
> > Regards
> > Marco
> >
> >
> >
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: user-unsubscribe@cassandra.apache.org
> For additional commands, e-mail: user-help@cassandra.apache.org
>
>
Re: too many logDroppedMessages and StatusLogger
Posted by Nate McCall <zz...@gmail.com>.
Are you using queries with a large number of arguments to an IN clause
on a partition key? If so, the coordinator has to:
- hold open the client request
- unwind the IN clause into individual statements
- scatter/gathering those statements around the cluster (each at the
requested consistency level!)
- pull it all back together and send it out
In extreme cases, this can flood internode messaging and make things
look slow even when the system is near idle.
On Fri, Mar 8, 2019 at 9:27 PM Marco Gasparini
<ma...@competitoor.com> wrote:
>
> Hi all,
>
> I cannot understand why I get the following logs, they appear every day at not fixed period of time. I saw them every 2 minutes or every 10 seconds, I cannot find any pattern.
> I took this very example here during an heavy workload of writes and reads but I get them also during a very little workload and without any active compaction/repair/streaming process and no high cpu/memory/iowait usage.
>
>> 2019-03-08 01:49:47,868 INFO [ScheduledTasks:1] MessagingService.java:1246 logDroppedMessages READ messages were dropped in last 5000 ms: 0 internal and 1 cross node. Mean internal dropped latency: 6357 ms and Mean cross-node dropped latency: 6556 ms
>> 2019-03-08 01:49:47,868 INFO [ScheduledTasks:1] StatusLogger.java:47 log Pool Name Active Pending Completed Blocked All Time Blocked
>> 2019-03-08 01:49:47,870 INFO [ScheduledTasks:1] StatusLogger.java:51 log MutationStage 0 0 17641121 0 0
>> 2019-03-08 01:49:47,870 INFO [ScheduledTasks:1] StatusLogger.java:51 log ViewMutationStage 0 0 0 0 0
>> 2019-03-08 01:49:47,870 INFO [ScheduledTasks:1] StatusLogger.java:51 log ReadStage 0 0 6851090 0 0
>> 2019-03-08 01:49:47,870 INFO [ScheduledTasks:1] StatusLogger.java:51 log RequestResponseStage 0 0 13646587 0 0
>> 2019-03-08 01:49:47,870 INFO [ScheduledTasks:1] StatusLogger.java:51 log ReadRepairStage 0 0 352884 0 0
>> 2019-03-08 01:49:47,870 INFO [ScheduledTasks:1] StatusLogger.java:51 log CounterMutationStage 0 0 0 0 0
>> 2019-03-08 01:49:47,870 INFO [ScheduledTasks:1] StatusLogger.java:51 log MiscStage 0 0 0 0 0
>> 2019-03-08 01:49:47,870 INFO [ScheduledTasks:1] StatusLogger.java:51 log CompactionExecutor 0 0 882478 0 0
>> 2019-03-08 01:49:47,871 INFO [ScheduledTasks:1] StatusLogger.java:51 log MemtableReclaimMemory 0 0 4101 0 0
>> 2019-03-08 01:49:47,871 INFO [ScheduledTasks:1] StatusLogger.java:51 log PendingRangeCalculator 0 0 7 0 0
>> 2019-03-08 01:49:47,871 INFO [ScheduledTasks:1] StatusLogger.java:51 log GossipStage 0 0 4399705 0 0
>> 2019-03-08 01:49:47,871 INFO [ScheduledTasks:1] StatusLogger.java:51 log SecondaryIndexManagement 0 0 0 0 0
>> 2019-03-08 01:49:47,871 INFO [ScheduledTasks:1] StatusLogger.java:51 log HintsDispatcher 0 0 2165 0 0
>> 2019-03-08 01:49:47,871 INFO [ScheduledTasks:1] StatusLogger.java:51 log MigrationStage 0 0 50 0 0
>> 2019-03-08 01:49:47,871 INFO [ScheduledTasks:1] StatusLogger.java:51 log MemtablePostFlush 0 0 4393 0 0
>> 2019-03-08 01:49:47,872 INFO [ScheduledTasks:1] StatusLogger.java:51 log PerDiskMemtableFlushWriter_0 0 0 4097 0 0
>> 2019-03-08 01:49:47,872 INFO [ScheduledTasks:1] StatusLogger.java:51 log ValidationExecutor 0 0 1565 0 0
>> 2019-03-08 01:49:47,872 INFO [ScheduledTasks:1] StatusLogger.java:51 log Sampler 0 0 0 0 0
>> 2019-03-08 01:49:47,872 INFO [ScheduledTasks:1] StatusLogger.java:51 log MemtableFlushWriter 0 0 4101 0 0
>> 2019-03-08 01:49:47,872 INFO [ScheduledTasks:1] StatusLogger.java:51 log InternalResponseStage 0 0 121813 0 0
>> 2019-03-08 01:49:47,872 INFO [ScheduledTasks:1] StatusLogger.java:51 log AntiEntropyStage 0 0 6997 0 0
>> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:51 log CacheCleanupExecutor 0 0 33 0 0
>> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:51 log Native-Transport-Requests 4 0 364526951 0 0
>> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:61 log CompactionManager 0 0
>> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:73 log MessagingService n/a 2/0
>> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:83 log Cache Type Size Capacity KeysToSave
>> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:85 log KeyCache 104856992 104857600 all
>> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:91 log RowCache 0 0 all
>> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:98 log Table Memtable ops,data
>> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:101 log system_distributed.parent_repair_history 0,0
>> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:101 log system_distributed.repair_history 0,0
>> 2019-03-08 01:49:47,873 INFO [ScheduledTasks:1] StatusLogger.java:101 log system_distributed.view_build_status 0,0
>> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log system.compaction_history 3,781
>> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log system.schema_aggregates 0,0
>> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log system.schema_triggers 0,0
>> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log system.size_estimates 2535,100788
>> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log system.paxos 0,0
>> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log system.views_builds_in_progress 0,0
>> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log system.batches 0,0
>> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log system.schema_keyspaces 0,0
>> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log system.sstable_activity 129,3974
>> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log system.batchlog 0,0
>> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log system.schema_columns 0,0
>> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log system.hints 0,0
>> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log system.IndexInfo 0,0
>> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log system.schema_columnfamilies 0,0
>> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log system.schema_functions 0,0
>> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log system.built_views 0,0
>> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log system.peer_events 0,0
>> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log system.range_xfers 0,0
>> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log system.peers 0,0
>> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log system.transferred_ranges 0,0
>> 2019-03-08 01:49:47,874 INFO [ScheduledTasks:1] StatusLogger.java:101 log system.schema_usertypes 0,0
>> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log system.local 0,0
>> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log system.available_ranges 0,0
>> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log system.prepared_statements 0,0
>> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log system_schema.columns 0,0
>> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log system_schema.types 0,0
>> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log system_schema.indexes 0,0
>> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log system_schema.keyspaces 0,0
>> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log system_schema.dropped_columns 0,0
>> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log system_schema.aggregates 0,0
>> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log system_schema.triggers 0,0
>> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log system_schema.tables 0,0
>> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log system_schema.views 0,0
>> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log system_schema.functions 0,0
>> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log web_history.web_pages_history 2851,402270519
>> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log _kibana.doc 0,0
>> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log scratchboard.job_ids_scratches 156810,13026241
>> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log elastic_admin.metadata 0,0
>> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log system_auth.roles 0,0
>> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log system_auth.role_members 0,0
>> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log system_auth.resource_role_permissons_index 0,0
>> 2019-03-08 01:49:47,875 INFO [ScheduledTasks:1] StatusLogger.java:101 log system_auth.role_permissions 0,0
>> 2019-03-08 01:49:47,876 INFO [ScheduledTasks:1] StatusLogger.java:101 log system_traces.sessions 0,0
>> 2019-03-08 01:49:47,876 INFO [ScheduledTasks:1] StatusLogger.java:101 log system_traces.events 0,0
>
>
> I have a 5 nodes cluster running Cassandra 3.11.3.5. During high workload I got 500k reads and about 1M writes (inserts and/or deletes) in about 2.5 hours, after that the workload goes down.
>
> any help is very appreciate.
>
> Regards
> Marco
>
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: user-unsubscribe@cassandra.apache.org
For additional commands, e-mail: user-help@cassandra.apache.org