cassandra-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Nate McCall <zznat...@gmail.com>
Subject Re: too many logDroppedMessages and StatusLogger
Date Mon, 11 Mar 2019 21:20:33 GMT
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.gasparini@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


Mime
View raw message