Uploaded image for project: 'Cassandra'
  1. Cassandra
  2. CASSANDRA-12182

redundant StatusLogger print out when both dropped message and long GC event happen

    XMLWordPrintableJSON

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Low
    • Resolution: Fixed
    • Fix Version/s: 4.0, 4.0-alpha1
    • Component/s: None
    • Labels:
    • Severity:
      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.

        Attachments

        1. 12182-trunk.txt
          2 kB
          Michał Szczygieł
        2. 12182-trunk.txt
          9 kB
          Michał Szczygieł
        3. 12182-trunk.txt
          9 kB
          Michał Szczygieł

          Activity

            People

            • Assignee:
              mychal Michał Szczygieł
              Reporter:
              weideng Wei Deng
              Authors:
              Michał Szczygieł
              Reviewers:
              Jason Brown
            • Votes:
              0 Vote for this issue
              Watchers:
              7 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: