Details
-
Bug
-
Status: Resolved
-
Low
-
Resolution: Fixed
-
None
-
Low
Description
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:
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
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.