cassandra-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Danil Smirnov (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (CASSANDRA-13095) Timeouts between nodes
Date Fri, 06 Jan 2017 23:50:59 GMT

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

Danil Smirnov commented on CASSANDRA-13095:
-------------------------------------------

Updated the patch with additional check for sleep value. Checking at that line would allow
to monitor incorrect average gap value through coalescing_debug option.

And just in case, a rough method to reproduce the problem:
1. Setup 2-nodes cluster with version 2.2.8 with -Dcassandra.coalescing_debug=true
2. Create test table:
{code}
CREATE KEYSPACE temp WITH replication = {'class': 'SimpleStrategy', 'replication_factor':
'2'};
CREATE TABLE temp.temp (
    id int PRIMARY KEY,
    value text
) WITH dclocal_read_repair_chance = 1.0;
{code}
3. Populate it with data:
{code}
import random
import string

from cassandra.cluster import Cluster
from cassandra import ConsistencyLevel

cluster = Cluster()
session = cluster.connect()

test_stmt = session.prepare("INSERT INTO temp.temp (id, value) VALUES (?, ?)")
test_stmt.consistency_level = ConsistencyLevel.ALL

for id in xrange(50000):
    value = "".join( [random.choice(string.letters) for i in xrange(100)] )
    session.execute(test_stmt, [id, value])
{code}
4. Add additional logging and replace apache-cassandra-2.2.8.jar with new one:
{code}
>From 607c4194036d0f33e64c7380724fca94cf47d284 Mon Sep 17 00:00:00 2001
From: Smirnov Danil <aulust@gmail.com>
Date: Wed, 4 Jan 2017 12:07:42 +0300
Subject: [PATCH] logging

---
 src/java/org/apache/cassandra/utils/CoalescingStrategies.java | 5 +++++
 1 file changed, 5 insertions(+)

diff --git a/src/java/org/apache/cassandra/utils/CoalescingStrategies.java b/src/java/org/apache/cassandra/utils/CoalescingStrategies.java
index 7dba97b..7598eef 100644
--- a/src/java/org/apache/cassandra/utils/CoalescingStrategies.java
+++ b/src/java/org/apache/cassandra/utils/CoalescingStrategies.java
@@ -290,6 +290,7 @@ public class CoalescingStrategies
         {
             if (delta > 2 * INTERVAL)
             {
+                logger.info("{} rollepoch", this);
                 // this sample is more than twice our interval ahead, so just clear our counters
completely
                 epoch = epoch(nanos);
                 sum = 0;
@@ -336,6 +337,10 @@ public class CoalescingStrategies
                 logSample(qm.timestampNanos());
 
             long averageGap = averageGap();
+            if (DEBUG_COALESCING && shouldLogAverage)
+            {
+                logger.info("{} sum expected {}, was {}", this, Arrays.stream(samples).sum()
- samples[ix(epoch - 1)], sum);
+            }
             debugGap(averageGap);
 
             int count = out.size();
-- 
2.7.4

{code}
5. Restart nodes, add  and run script to infinitely fetch data:
{code}
import random

from cassandra.cluster import Cluster
from cassandra import ConsistencyLevel

cluster = Cluster()
session = cluster.connect()

test_stmt = session.prepare("SELECT * FROM temp.temp WHERE id in ?")
test_stmt.consistency_level = ConsistencyLevel.ONE
test_stmt.fetch_size = None

while (True):
    ids = [(random.randrange(50000)) for i in xrange(100)]
    session.execute(test_stmt, [ids])
{code}
6. At this point everything supposed to be normal (see system.log for sum variable value).
Since between starting nodes and starting script some time had passed. Maybe sum will differ
for gossipMessages (probably) coalescing, but it's value is very low.
7. Restart one of the nodes. Now you will be able to see sum growing very fast for smallMessages
tcp connection, exceeding reasonable values. After hours or days it will result in thread
block.

> Timeouts between nodes
> ----------------------
>
>                 Key: CASSANDRA-13095
>                 URL: https://issues.apache.org/jira/browse/CASSANDRA-13095
>             Project: Cassandra
>          Issue Type: Bug
>            Reporter: Danil Smirnov
>            Priority: Minor
>         Attachments: 13095-2.1.patch
>
>
> Recently I've run into a problem with heavily loaded cluster when sometimes messages
between certain nodes become blocked with no reason.
> It looks like the same situation that described here https://issues.apache.org/jira/browse/CASSANDRA-12676?focusedCommentId=15736166&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-15736166
> Thread dump showed infinite loop here: https://github.com/apache/cassandra/blob/a8a43dd32eb92406d7d8b105e08c68b3d5c7df49/src/java/org/apache/cassandra/utils/CoalescingStrategies.java#L109
> Apparently the problem is in the initial value of epoch filed in TimeHorizonMovingAverageCoalescingStrategy
class. When it's value is not evenly divisible by BUCKET_INTERVAL, ix(epoch-1) does not point
to the correct bucket. As a result, sum gradually increases and, upon reaching MEASURED_INTERVAL,
averageGap becomes 0 and thread blocks.
> It's hard to reproduce because it takes a long time for sum to grow and when no messages
are send for some time, sum becomes 0 https://github.com/apache/cassandra/blob/a8a43dd32eb92406d7d8b105e08c68b3d5c7df49/src/java/org/apache/cassandra/utils/CoalescingStrategies.java#L301
and bug is no longer reproducible (until connection between nodes is re-created).
> I've added a patch which should fix the problem. Don't know if it would be of any help
since CASSANDRA-12676 will apparently disable this behaviour. One note about performance regressions
though. There is a small chance it being result of the bug described here, so it might be
worth testing performance after fixes and/or tuning the algorithm.



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Mime
View raw message