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] [Commented] (CASSANDRA-12182) redundant StatusLogger print out when both dropped message and long GC event happen
Date Wed, 12 Oct 2016 23:19:20 GMT

    [ https://issues.apache.org/jira/browse/CASSANDRA-12182?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15570188#comment-15570188
] 

Wei Deng commented on CASSANDRA-12182:
--------------------------------------

[~KurtG] Personally I don't have much issue with the current logging level for StatusLogger.
When the node is suffering, either because it's dropping non-TRACE messages, or because it's
exceeding the 1sec gc_warn_threshold_in_ms threshold, I'd like to see StatusLogger to give
me more information for post-mortem analysis and I don't want to change to DEBUG level to
see it. Note "post-mortem" is the key here as you won't know when this will happen and if
you have to switch to DEBUG level to see the message likely it will be too late.

bq. I think replacing the log messages with StatusLogger is busy would somewhat defeat the
purpose.
Can you elaborate why you think avoiding duplicate StatusLogger printing "defeat the purpose"?
The StatusLogger usually only takes 100-200ms to finish printing its state. If at the time
StatusLogger is printing, another StatusLogger gets triggered and print again, it mostly just
adds duplicate information which makes log messages crowded without adding any more useful
insight.

> 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
>              Labels: lhf
>
> 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