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

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

Agile BoardAttach filesAttach ScreenshotBulk Copy AttachmentsBulk Move AttachmentsVotersWatch issueWatchersCreate sub-taskConvert to sub-taskMoveLinkCloneLabelsUpdate Comment AuthorReplace String in CommentUpdate Comment VisibilityDelete Comments
    XMLWordPrintableJSON

Details

    • Bug
    • Status: Resolved
    • Low
    • Resolution: Fixed
    • 4.0-alpha1, 4.0
    • 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.

      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

          This comment will be Viewable by All Users Viewable by All Users
          Cancel

          People

            mychal Michał Szczygieł Assign to me
            weideng Wei Deng
            Michał Szczygieł
            Jason Brown
            Votes:
            0 Vote for this issue
            Watchers:
            7 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              Slack

                Issue deployment