cassandra-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Wei Deng (JIRA)" <j...@apache.org>
Subject [jira] [Created] (CASSANDRA-12182) redundant StatusLogger print out when both dropped message and long GC event happen
Date Tue, 12 Jul 2016 23:07:20 GMT
Wei Deng created CASSANDRA-12182:
------------------------------------

             Summary: redundant StatusLogger print out when both dropped message and long
GC event happen
                 Key: CASSANDRA-12182
                 URL: https://issues.apache.org/jira/browse/CASSANDRA-12182
             Project: Cassandra
          Issue Type: Bug
            Reporter: Wei Deng
            Priority: Minor


I was stress testing a C* 3.0 environment and it appears that when the CPU is running low,
HINT and MUTATION messages will start to get dropped, and the GC thread can also get some
really long-running GC, and I'd get some redundant log entries in system.log like the following:

{noformat}
WARN  [Service Thread] 2016-07-12 22:48:45,748  GCInspector.java:282 - G1 Young Generation
GC in 522ms.  G1 Eden Space: 68157440 -> 0; G1 Old Gen: 3376113224 -> 3468387912; G1
Survivor Space: 24117248 -> 0; 
INFO  [Service Thread] 2016-07-12 22:48:45,763  StatusLogger.java:52 - Pool Name         
          Active   Pending      Completed   Blocked  All Time Blocked
INFO  [ScheduledTasks:1] 2016-07-12 22:48:45,775  MessagingService.java:983 - MUTATION messages
were dropped in last 5000 ms: 419 for internal timeout and 0 for cross node timeout
INFO  [ScheduledTasks:1] 2016-07-12 22:48:45,776  MessagingService.java:983 - HINT messages
were dropped in last 5000 ms: 89 for internal timeout and 0 for cross node timeout
INFO  [ScheduledTasks:1] 2016-07-12 22:48:45,776  StatusLogger.java:52 - Pool Name       
            Active   Pending      Completed   Blocked  All Time Blocked
INFO  [ScheduledTasks:1] 2016-07-12 22:48:45,798  StatusLogger.java:56 - MutationStage   
                32      4194       32997234         0                 0

INFO  [ScheduledTasks:1] 2016-07-12 22:48:45,798  StatusLogger.java:56 - ViewMutationStage
                0         0              0         0                 0

INFO  [ScheduledTasks:1] 2016-07-12 22:48:45,799  StatusLogger.java:56 - ReadStage       
                 0         0            940         0                 0

INFO  [Service Thread] 2016-07-12 22:48:45,800  StatusLogger.java:56 - MutationStage     
              32      4363       32997333         0                 0

INFO  [Service Thread] 2016-07-12 22:48:45,801  StatusLogger.java:56 - ViewMutationStage 
               0         0              0         0                 0

INFO  [Service Thread] 2016-07-12 22:48:45,801  StatusLogger.java:56 - ReadStage         
               0         0            940         0                 0

INFO  [Service Thread] 2016-07-12 22:48:45,802  StatusLogger.java:56 - RequestResponseStage
             0         0       11094437         0                 0

INFO  [Service Thread] 2016-07-12 22:48:45,802  StatusLogger.java:56 - ReadRepairStage   
               0         0              5         0                 0

INFO  [ScheduledTasks:1] 2016-07-12 22:48:45,803  StatusLogger.java:56 - RequestResponseStage
             4         0       11094509         0                 0

INFO  [ScheduledTasks:1] 2016-07-12 22:48:45,807  StatusLogger.java:56 - ReadRepairStage 
                 0         0              5         0                 0

INFO  [ScheduledTasks:1] 2016-07-12 22:48:45,808  StatusLogger.java:56 - CounterMutationStage
             0         0              0         0                 0

INFO  [ScheduledTasks:1] 2016-07-12 22:48:45,809  StatusLogger.java:56 - MiscStage       
                 0         0              0         0                 0

INFO  [ScheduledTasks:1] 2016-07-12 22:48:45,809  StatusLogger.java:56 - CompactionExecutor
               2        62           1234         0                 0

INFO  [ScheduledTasks:1] 2016-07-12 22:48:45,810  StatusLogger.java:56 - MemtableReclaimMemory
            0         0             79         0                 0

INFO  [ScheduledTasks:1] 2016-07-12 22:48:45,810  StatusLogger.java:56 - PendingRangeCalculator
           0         0              3         0                 0

INFO  [ScheduledTasks:1] 2016-07-12 22:48:45,819  StatusLogger.java:56 - GossipStage     
                 0         0           5214         0                 0

INFO  [ScheduledTasks:1] 2016-07-12 22:48:45,820  StatusLogger.java:56 - SecondaryIndexManagement
         0         0              3         0                 0

INFO  [ScheduledTasks:1] 2016-07-12 22:48:45,820  StatusLogger.java:56 - HintsDispatcher 
                 1         2             36         0                 0

INFO  [ScheduledTasks:1] 2016-07-12 22:48:45,821  StatusLogger.java:56 - MigrationStage  
                 0         0              0         0                 0

INFO  [ScheduledTasks:1] 2016-07-12 22:48:45,822  StatusLogger.java:56 - MemtablePostFlush
                1         3            115         0                 0

INFO  [Service Thread] 2016-07-12 22:48:45,830  StatusLogger.java:56 - CounterMutationStage
             0         0              0         0                 0

INFO  [Service Thread] 2016-07-12 22:48:45,831  StatusLogger.java:56 - MiscStage         
               0         0              0         0                 0

INFO  [Service Thread] 2016-07-12 22:48:45,831  StatusLogger.java:56 - CompactionExecutor
               2        62           1234         0                 0

INFO  [Service Thread] 2016-07-12 22:48:45,832  StatusLogger.java:56 - MemtableReclaimMemory
            0         0             79         0                 0

INFO  [Service Thread] 2016-07-12 22:48:45,832  StatusLogger.java:56 - PendingRangeCalculator
           0         0              3         0                 0

INFO  [Service Thread] 2016-07-12 22:48:45,833  StatusLogger.java:56 - GossipStage       
               0         0           5214         0                 0

INFO  [Service Thread] 2016-07-12 22:48:45,839  StatusLogger.java:56 - SecondaryIndexManagement
         0         0              3         0                 0

INFO  [Service Thread] 2016-07-12 22:48:45,840  StatusLogger.java:56 - HintsDispatcher   
               1         2             36         0                 0

INFO  [Service Thread] 2016-07-12 22:48:45,843  StatusLogger.java:56 - MigrationStage    
               0         0              0         0                 0

INFO  [Service Thread] 2016-07-12 22:48:45,844  StatusLogger.java:56 - MemtablePostFlush 
               1         3            115         0                 0

INFO  [Service Thread] 2016-07-12 22:48:45,844  StatusLogger.java:56 - ValidationExecutor
               0         0              0         0                 0

INFO  [Service Thread] 2016-07-12 22:48:45,845  StatusLogger.java:56 - Sampler           
               0         0              0         0                 0

INFO  [Service Thread] 2016-07-12 22:48:45,846  StatusLogger.java:56 - MemtableFlushWriter
              2         2             79         0                 0

INFO  [Service Thread] 2016-07-12 22:48:45,846  StatusLogger.java:56 - InternalResponseStage
            0         0        1978269         0                 0

INFO  [Service Thread] 2016-07-12 22:48:45,847  StatusLogger.java:56 - AntiEntropyStage  
               0         0              0         0                 0

INFO  [Service Thread] 2016-07-12 22:48:45,847  StatusLogger.java:56 - CacheCleanupExecutor
             0         0              0         0                 0

INFO  [Service Thread] 2016-07-12 22:48:45,848  StatusLogger.java:56 - Native-Transport-Requests
      128       133        5903870         8           1534827

INFO  [Service Thread] 2016-07-12 22:48:45,848  StatusLogger.java:66 - CompactionManager 
               2        18
INFO  [ScheduledTasks:1] 2016-07-12 22:48:45,870  StatusLogger.java:56 - ValidationExecutor
               0         0              0         0                 0

INFO  [Service Thread] 2016-07-12 22:48:45,872  StatusLogger.java:78 - MessagingService  
             n/a      0/16
INFO  [ScheduledTasks:1] 2016-07-12 22:48:45,884  StatusLogger.java:56 - Sampler         
                 0         0              0         0                 0

INFO  [Service Thread] 2016-07-12 22:48:45,885  StatusLogger.java:88 - Cache Type        
            Size                 Capacity               KeysToSave
INFO  [ScheduledTasks:1] 2016-07-12 22:48:45,885  StatusLogger.java:56 - MemtableFlushWriter
              2         2             79         0                 0

INFO  [Service Thread] 2016-07-12 22:48:45,886  StatusLogger.java:90 - KeyCache          
           14240                104857600                      all
INFO  [ScheduledTasks:1] 2016-07-12 22:48:45,887  StatusLogger.java:56 - InternalResponseStage
            0         0        1978269         0                 0

INFO  [Service Thread] 2016-07-12 22:48:45,887  StatusLogger.java:96 - RowCache          
               0                        0                      all
INFO  [ScheduledTasks:1] 2016-07-12 22:48:45,888  StatusLogger.java:56 - AntiEntropyStage
                 0         0              0         0                 0
{noformat}

This makes the log entries harder to read. If we can make StatusLogger code to be single entry
and subsequent call will just give up and print out a log like "StatusLogger is busy", that
should help to make the log clean.



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Mime
View raw message