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 <marco.gaspar...@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-unsubscr...@cassandra.apache.org For additional commands, e-mail: user-h...@cassandra.apache.org
