[
https://issues.apache.org/jira/browse/CASSANDRA-12182?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15570201#comment-15570201
]
Kurt Greaves commented on CASSANDRA-12182:
------------------------------------------
Sorry that was my misunderstanding, I didn't realise you were just targetting
"duplicate" entries. In that case that makes sense. I suppose a cooldown period
for StatusLogger messages is what you're looking for then? In that case I'd
probably say something like restricting messages to once every 10 seconds or so
would be reasonable. Just my 2c.
> 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)
