[
https://issues.apache.org/jira/browse/CASSANDRA-12182?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16238426#comment-16238426
]
Michał Szczygieł commented on CASSANDRA-12182:
----------------------------------------------
But {{AppenderBase#doAppend}} is called only from 2 threads created by
{{ExecutorService}} in {{submitTwoLogRequestsConcurrently}}, essentially
leaving thread that test is executed on without using {{InMemoryAppender}}
instance as a monitor to read {{InMemoryAppender#events}}, so unless I'm
totally missing it we're not guaranteed {{AppenderBase#doAppend}} happens
before read of {{events}}.
> 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
> Assignee: Michał Szczygieł
> Priority: Minor
> Labels: lhf
> Attachments: 12182-trunk.txt, 12182-trunk.txt, 12182-trunk.txt
>
>
> 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.4.14#64029)
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscr...@cassandra.apache.org
For additional commands, e-mail: commits-h...@cassandra.apache.org
