[ https://issues.apache.org/jira/browse/CASSANDRA-12182?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Jeff Jirsa updated CASSANDRA-12182: ----------------------------------- Comment: was deleted (was: I realize it’s s pretty simple patch, but couldn’t nospamlogger give us this same behavior?) > 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 > > > 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