You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@cassandra.apache.org by "Michał Szczygieł (JIRA)" <ji...@apache.org> on 2017/11/03 23:10:00 UTC

[jira] [Comment Edited] (CASSANDRA-12182) redundant StatusLogger print out when both dropped message and long GC event happen

    [ https://issues.apache.org/jira/browse/CASSANDRA-12182?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16238548#comment-16238548 ] 

Michał Szczygieł edited comment on CASSANDRA-12182 at 11/3/17 11:09 PM:
------------------------------------------------------------------------

You're right (obviously). Feel free to remove {{InMemoryAppender#getEvents}} from my latest patch and replace it with direct field access. But please don't use previous patch, because test would incorrectly fail when time ranges are not connected ({{Range#intersect}} would throw {{IllegalArgumentException}} in such case). utests for the latest patch: [https://circleci.com/gh/mszczygiel/cassandra/4] 


was (Author: mychal):
You're right (obviously). Feel free to remove {{InMemoryAppender#getEvents}} from my latest patch and replace it with direct field access. But please don't use previous patch, because test would incorrectly fail when time ranges are not connected ({{Range.intersect}} would throw {{IllegalArgumentException}} in such case). utests for the latest patch: [https://circleci.com/gh/mszczygiel/cassandra/4] 

> 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-unsubscribe@cassandra.apache.org
For additional commands, e-mail: commits-help@cassandra.apache.org