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