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

Kurt Greaves edited comment on CASSANDRA-12182 at 10/12/16 10:42 PM:
---------------------------------------------------------------------

You can set the logging level for the statuslogger to warn to avoid those error 
messages.
{code}nodetool setlogginglevel org.apache.cassandra.utils.StatusLogger 
WARN{code}

or you can set the equivalent in logback.xml. Maybe INFO is noisy but I think 
replacing the log messages with StatusLogger is busy would somewhat defeat the 
purpose. 

-edit: Having said that, maybe INFO is too high, and this detail needs to drop 
to debug. From experience managing a lot of clusters the actual GCInspector 
message is the useful output in this case. However StatusLogger is also 
triggered from other events. Although those are all paired with other log 
messages, which as in this case, are probably more useful than the statuslogger 
output. StatusLogger seems to me to be for much more specific debugging of a 
problem.


was (Author: kurtg):
You can set the logging level for the statuslogger to warn to avoid those error 
messages.
{code}nodetool setlogginglevel org.apache.cassandra.utils.StatusLogger 
WARN{code}

or you can set the equivalent in logback.xml. Maybe INFO is noisy but I think 
replacing the log messages with StatusLogger is busy would somewhat defeat the 
purpose.

> 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)

Reply via email to