Return-Path: X-Original-To: archive-asf-public-internal@cust-asf2.ponee.io Delivered-To: archive-asf-public-internal@cust-asf2.ponee.io Received: from cust-asf.ponee.io (cust-asf.ponee.io [163.172.22.183]) by cust-asf2.ponee.io (Postfix) with ESMTP id 67D6A200B7A for ; Mon, 5 Sep 2016 19:28:16 +0200 (CEST) Received: by cust-asf.ponee.io (Postfix) id 663F5160ABC; Mon, 5 Sep 2016 17:28:16 +0000 (UTC) Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by cust-asf.ponee.io (Postfix) with SMTP id E0E91160AB0 for ; Mon, 5 Sep 2016 19:28:14 +0200 (CEST) Received: (qmail 38055 invoked by uid 500); 5 Sep 2016 17:28:13 -0000 Mailing-List: contact user-help@cassandra.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: user@cassandra.apache.org Delivered-To: mailing list user@cassandra.apache.org Received: (qmail 38045 invoked by uid 99); 5 Sep 2016 17:28:13 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd1-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 05 Sep 2016 17:28:13 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd1-us-west.apache.org (ASF Mail Server at spamd1-us-west.apache.org) with ESMTP id E0125C7EBA for ; Mon, 5 Sep 2016 17:28:12 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd1-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: 3.079 X-Spam-Level: *** X-Spam-Status: No, score=3.079 tagged_above=-999 required=6.31 tests=[DKIM_SIGNED=0.1, DKIM_VALID=-0.1, DKIM_VALID_AU=-0.1, HTML_MESSAGE=2, KAM_LINEPADDING=1.2, RCVD_IN_DNSWL_NONE=-0.0001, RCVD_IN_MSPIKE_H3=-0.01, RCVD_IN_MSPIKE_WL=-0.01, SPF_PASS=-0.001] autolearn=disabled Authentication-Results: spamd1-us-west.apache.org (amavisd-new); dkim=pass (2048-bit key) header.d=gmail.com Received: from mx2-lw-eu.apache.org ([10.40.0.8]) by localhost (spamd1-us-west.apache.org [10.40.0.7]) (amavisd-new, port 10024) with ESMTP id rbWB4yY1Rvhy for ; Mon, 5 Sep 2016 17:28:10 +0000 (UTC) Received: from mail-yw0-f172.google.com (mail-yw0-f172.google.com [209.85.161.172]) by mx2-lw-eu.apache.org (ASF Mail Server at mx2-lw-eu.apache.org) with ESMTPS id 54A825FBE2 for ; Mon, 5 Sep 2016 17:28:09 +0000 (UTC) Received: by mail-yw0-f172.google.com with SMTP id j1so21106663ywb.2 for ; Mon, 05 Sep 2016 10:28:09 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113; h=mime-version:in-reply-to:references:from:date:message-id:subject:to; bh=L/+7zvLUe49/V9PvDsiLEtP5mPwY9CSnokVBnR2uSnY=; b=em2PLq60yl5xm0IYfUSeDNyjJaytqbnDZF9c6aofnuW+z96TmGObCjuOrY8gxS7l90 TC+RG+IH/If1gVGgW6G089ZnCA8sQ0T26f7cku/h1bWYKZsfWIBv5zx9uLDv9+ZGjUCP 441fbeRhhX+C5dQoeA99i2qcf5oY5JcsTK7yVAb2uOCVCKcehynlApiVwwNbXDCQQExy hUMr6XTgqAU7hqc7yWeCuIjxEu740oPuyydDIkz0/CwROjzlX3xKXaGrDUpgTMYBmDGI G7fWFXcgEjaqfpVK2USqujJwoPmTw7awK6F0uIDJ4iLm6mT0AvLbWe+2/I6Yet6OQyKD oyBQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20130820; h=x-gm-message-state:mime-version:in-reply-to:references:from:date :message-id:subject:to; bh=L/+7zvLUe49/V9PvDsiLEtP5mPwY9CSnokVBnR2uSnY=; b=SZvq2wus2g0c85K55mEfC8Opd1eSW0aJNCO+UAn/UT/RWdlJPltDWIAXtQPNjzPXha HH4679jDwwmkZ7Qjk4zdfOteyB2dY+7WQAI60+AWgrKG3pxTnfjVI4jbNYq0cySbAVin TCimYc5oYXYZxWI6k5vWDaYBuapxn63UmqT+sOGKZo30Zwwa/YhLjVP56BFlE8hey1fm yT9A1PH+tx9EphjIsrPLewI2OQZxcah85MkhP/QaAwZfyuKTZLTuJfSFzpwG19u6r6im BBQQ2NDwS3BLnj1jPicll3/IpDN52mj/ZOefJkHg7G76zni/i0B+6TbKxWCn31iTn4Yx oVCg== X-Gm-Message-State: AE9vXwNX67nRS9WDRlQwJOgfZbuGemXWKckKowZq2NWSsqOqFCS9YpSgeCZ9P0sYNAfMw3m81NAPk+sOiiHhqw== X-Received: by 10.129.108.21 with SMTP id h21mr8853948ywc.153.1473096482490; Mon, 05 Sep 2016 10:28:02 -0700 (PDT) MIME-Version: 1.0 Received: by 10.37.52.5 with HTTP; Mon, 5 Sep 2016 10:28:01 -0700 (PDT) In-Reply-To: <1313955902.1368282.1473086509708@mail.yahoo.com> References: <7E0D86054CA325B1.1DAF7965-ADCB-4607-9396-50AC3926F952@mail.outlook.com> <1114137226.1184009.1473078942507@mail.yahoo.com> <1313955902.1368282.1473086509708@mail.yahoo.com> From: Anshu Vajpayee Date: Mon, 5 Sep 2016 22:58:01 +0530 Message-ID: Subject: Re: Read timeouts on primary key queries To: user@cassandra.apache.org, Romain Hardouin Content-Type: multipart/alternative; boundary=001a114c5e648f113c053bc60084 archived-at: Mon, 05 Sep 2016 17:28:16 -0000 --001a114c5e648f113c053bc60084 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: quoted-printable We have seen read time out issue in cassandra due to high droppable tombstone ratio for repository. Please check for high droppable tombstone ratio for your repo. On Mon, Sep 5, 2016 at 8:11 PM, Romain Hardouin wrote= : > Yes dclocal_read_repair_chance will reduce the cross-DC traffic and > latency, so you can swap the values ( https://issues.apache.org/ > jira/browse/CASSANDRA-7320 ). I guess the sstable_size_in_mb was set to > 50 because back in the day (C* 1.0) the default size was way too small: 5 > MB. So maybe someone in your company tried "10 * the default" i.e. 50 MB. > Now the default is 160 MB. I don't say to change the value but just keep = in > mind that you're using a small value here, it could help you someday. > > Regarding the cells, the histograms shows an *estimation* of the min, p50= , > ..., p99, max of cells based on SSTables metadata. On your screenshot, th= e > Max is 4768. So you have a partition key with ~ 4768 cells. The p99 is > 1109, so 99% of your partition keys have less than (or equal to) 1109 > cells. > You can see these data of a given sstable with the tool sstablemetadata. > > Best, > > Romain > > > > Le Lundi 5 septembre 2016 15h17, Joseph Tech a > =C3=A9crit : > > > Thanks, Romain . We will try to enable the DEBUG logging (assuming it > won't clog the logs much) . Regarding the table configs, read_repair_chan= ce > must be carried over from older versions - mostly defaults. I think sstab= le_size_in_mb > was set to limit the max SSTable size, though i am not sure on the reason > for the 50 MB value. > > Does setting dclocal_read_repair_chance help in reducing cross-DC traffic > (haven't looked into this parameter, just going by the name). > > By the cell count definition : is it incremented based on the number of > writes for a given name(key?) and value. This table is heavy on reads and > writes. If so, the value should be much higher? > > On Mon, Sep 5, 2016 at 7:35 AM, Romain Hardouin > wrote: > > Hi, > > Try to put org.apache.cassandra.db. ConsistencyLevel at DEBUG level, it > could help to find a regular pattern. By the way, I see that you have set= a > global read repair chance: > read_repair_chance =3D 0.1 > And not the local read repair: > dclocal_read_repair_chance =3D 0.0 > Is there any reason to do that or is it just the old (pre 2.0.9) default > configuration? > > The cell count is the number of triplets: (name, value, timestamp) > > Also, I see that you have set sstable_size_in_mb at 50 MB. What is the > rational behind this? (Yes I'm curious :-) ). Anyway your "SSTables per > read" are good. > > Best, > > Romain > > Le Lundi 5 septembre 2016 13h32, Joseph Tech a > =C3=A9crit : > > > Hi Ryan, > > Attached are the cfhistograms run within few mins of each other. On the > surface, don't see anything which indicates too much skewing (assuming > skewing =3D=3Dkeys spread across many SSTables) . Please confirm. Related= to > this, what does the "cell count" metric indicate ; didn't find a clear > explanation in the documents. > > Thanks, > Joseph > > > On Thu, Sep 1, 2016 at 6:30 PM, Ryan Svihla wrote: > > Have you looked at cfhistograms/tablehistograms your data maybe just > skewed (most likely explanation is probably the correct one here) > > Regard, > > Ryan Svihla > > _____________________________ > From: Joseph Tech > Sent: Wednesday, August 31, 2016 11:16 PM > Subject: Re: Read timeouts on primary key queries > To: > > > > Patrick, > > The desc table is below (only col names changed) : > > CREATE TABLE db.tbl ( > id1 text, > id2 text, > id3 text, > id4 text, > f1 text, > f2 map, > f3 map, > created timestamp, > updated timestamp, > PRIMARY KEY (id1, id2, id3, id4) > ) WITH CLUSTERING ORDER BY (id2 ASC, id3 ASC, id4 ASC) > AND bloom_filter_fp_chance =3D 0.01 > AND caching =3D '{"keys":"ALL", "rows_per_partition":"NONE"}' > AND comment =3D '' > AND compaction =3D {'sstable_size_in_mb': '50', 'class': > 'org.apache.cassandra.db. compaction. LeveledCompactionStrategy'} > AND compression =3D {'sstable_compression': 'org.apache.cassandra.io. > compress.LZ4Compressor'} > AND dclocal_read_repair_chance =3D 0.0 > AND default_time_to_live =3D 0 > AND gc_grace_seconds =3D 864000 > AND max_index_interval =3D 2048 > AND memtable_flush_period_in_ms =3D 0 > AND min_index_interval =3D 128 > AND read_repair_chance =3D 0.1 > AND speculative_retry =3D '99.0PERCENTILE'; > > and the query is select * from tbl where id1=3D? and id2=3D? and id3=3D? = and > id4=3D? > > The timeouts happen within ~2s to ~5s, while the successful calls have av= g > of 8ms and p99 of 15s. These times are seen from app side, the actual que= ry > times would be slightly lower. > > Is there a way to capture traces only when queries take longer than a > specified duration? . We can't enable tracing in production given the > volume of traffic. We see that the same query which timed out works fine > later, so not sure if the trace of a successful run would help. > > Thanks, > Joseph > > > On Wed, Aug 31, 2016 at 8:05 PM, Patrick McFadin > wrote: > > If you are getting a timeout on one table, then a mismatch of RF and node > count doesn't seem as likely. > > Time to look at your query. You said it was a 'select * from table where > key=3D?' type query. I would next use the trace facility in cqlsh to > investigate further. That's a good way to find hard to find issues. You > should be looking for clear ledge where you go from single digit ms to 4 = or > 5 digit ms times. > > The other place to look is your data model for that table if you want to > post the output from a desc table. > > Patrick > > > > On Tue, Aug 30, 2016 at 11:07 AM, Joseph Tech > wrote: > > On further analysis, this issue happens only on 1 table in the KS which > has the max reads. > > @Atul, I will look at system health, but didnt see anything standing out > from GC logs. (using JDK 1.8_92 with G1GC). > > @Patrick , could you please elaborate the "mismatch on node count + RF" > part. > > On Tue, Aug 30, 2016 at 5:35 PM, Atul Saroha > wrote: > > There could be many reasons for this if it is intermittent. CPU usage + > I/O wait status. As read are I/O intensive, your IOPS requirement should = be > met that time load. Heap issue if CPU is busy for GC only. Network health > could be the reason. So better to look system health during that time whe= n > it comes. > > ------------------------------ ------------------------------ > ------------------------------ --------------------------- > Atul Saroha > *Lead Software Engineer* > *M*: +91 8447784271 *T*: +91 124-415-6069 *EXT*: 12369 > Plot # 362, ASF Centre - Tower A, Udyog Vihar, > Phase -4, Sector 18, Gurgaon, Haryana 122016, INDIA > > On Tue, Aug 30, 2016 at 5:10 PM, Joseph Tech > wrote: > > Hi Patrick, > > The nodetool status shows all nodes up and normal now. From OpsCenter > "Event Log" , there are some nodes reported as being down/up etc. during > the timeframe of timeout, but these are Search workload nodes from the > remote (non-local) DC. The RF is 3 and there are 9 nodes per DC. > > Thanks, > Joseph > > On Mon, Aug 29, 2016 at 11:07 PM, Patrick McFadin > wrote: > > You aren't achieving quorum on your reads as the error is explains. That > means you either have some nodes down or your topology is not matching up= . > The fact you are using LOCAL_QUORUM might point to a datacenter mis-match > on node count + RF. > > What does your nodetool status look like? > > Patrick > > On Mon, Aug 29, 2016 at 10:14 AM, Joseph Tech > wrote: > > Hi, > > We recently started getting intermittent timeouts on primary key queries > (select * from table where key=3D) > > The error is : com.datastax.driver.core.excep tions.ReadTimeoutException: > Cassandra timeout during read query at consistency LOCAL_QUORUM (2 > responses were required but only 1 replica > a responded) > > The same query would work fine when tried directly from cqlsh. There are > no indications in system.log for the table in question, though there were > compactions in progress for tables in another keyspace which is more > frequently accessed. > > My understanding is that the chances of primary key queries timing out is > very minimal. Please share the possible reasons / ways to debug this issu= e. > > We are using Cassandra 2.1 (DSE 4.8.7). > > Thanks, > Joseph > > > > > > > > > > > > > > > > > > --=20 *Regards,* *Anshu * --001a114c5e648f113c053bc60084 Content-Type: text/html; charset=UTF-8 Content-Transfer-Encoding: quoted-printable
We have seen read time out issue in cassandra due to high dropp= able tombstone ratio for repository.=C2=A0

Please check for high dropp= able tombstone ratio for your repo.=C2=A0

On Mon, Sep 5, 2016 at 8:11 PM, Romain = Hardouin <romainh_ml@yahoo.fr> wrote:
Yes=C2=A0dclocal_read_repair_chance will reduce the= cross-DC traffic and latency, so you can swap the values (=C2=A0https://issues.apache.org/jira/bro= wse/CASSANDRA-7320=C2=A0). I gues= s the sstable_size_in_mb was set to 50 because back in the day (C* 1.0) the= default size was way too small:=C2=A05 MB. So maybe someone in your compa= ny tried "10 * the default" i.e. 50 MB. Now the default is 160 MB= . I don't say to change the value but just keep in mind that you're= using a small value here, it could help you someday.

<= span style=3D"font-size:13px">Regarding the cells, the histograms shows an = *estimation* of the min, p50, ..., p99, max of cells based on SSTables meta= data. On your screenshot, the Max is 4768. So you have a partition key with= ~ 4768 cells. The p99 is 1109, so 99% of your partition keys have less tha= n (or equal to) 1109 cells.=C2=A0
You can see these data of a given sstable with the tool= sstablemetadata.

Best,

Romain



Le Lundi 5 septembre 2016 15h17, Joseph Tech <= jaalex.tech@gmai= l.com> a =C3=A9crit :


Thanks, Romain . We will try to enable= the DEBUG logging (assuming it won't clog the logs much) . Regarding t= he table configs,=C2=A0read_repair_chance must be=C2=A0carried= over from older versions - mostly defaults. I think=C2=A0sstable_siz= e_in_mb was set to limit the max SSTable size, though i am not sure on the = reason for the 50 MB value.
Does set= ting dclocal_read_repair_chance help in reducing cross-DC traf= fic (haven't looked into this parameter, just going by the name).

By the cell count definition : is it= incremented based on the number of writes for a given name(key?) and value= . This table is heavy on reads and writes. If so, the value should be much = higher?

On Mon, Sep 5, 2016 at 7:35 AM, Romain Hardouin <romainh_ml@yahoo.fr> wrote:
Hi,

Try to put=C2=A0org.apache.cassandra.db. ConsistencyLevel at DEBUG level, it could h= elp to find a regular pattern. By the way, I see that you have set a global= read repair chance:
=C2=A0 =C2=A0=C2=A0rea= d_repair_chance =3D 0.1
And not the local read repair:
=C2=A0 =C2=A0 dclocal_read_repair_chance =3D 0.0
Is there any reason to do tha= t or is it just the old (pre 2.0.9) default configuration?=C2=A0

The cell count is the number of triplets: (name,= value, timestamp)

Also, I see that y= ou have set=C2=A0sstable_size_in_mb a= t 50 MB. What is the rational behind this? (Yes I'm curious :-) ). Anyw= ay your "SSTables per read" are good.

Best,

Romain

Le Lundi 5 septembre 2016 13h32, Joseph Tech <jaalex.tech@gmail.com> a =C3=A9crit :


Hi Rya= n,

Attached are the cfhistograms run within few mins of each other. = On the surface, don't see anything which indicates too much skewing (as= suming skewing =3D=3Dkeys spread across many SSTables) . Please confirm. Re= lated to this, what does the "cell count" metric indicate ; didn&= #39;t find a clear explanation in the documents.

Thanks,
Joseph

On Thu, Sep 1, 2016 = at 6:30 PM, Ryan Svihla <rs@foundev.pro&g= t; wrote:
Have you looked at cfhistograms/tablehistograms your data ma= ybe just skewed (most likely explanation is probably the correct one here)<= br clear=3D"none">
Regard,

Ryan Svihla

_____________________________=
From: Joseph Tech <jaalex= .tech@gmail.com>
Sent: Wednesday, August 31, 2016 = 11:16 PM
Subject: Re: Read timeouts on primary key querie= s
To: <user@cassandra= .apache.org>
=


Patrick,

The desc table is below (only col na= mes changed) :=C2=A0

<= /font>
CREATE TABLE db.tbl (
=C2=A0 =C2=A0 id1 text,
=C2=A0 =C2=A0 id2 text,
=C2=A0 =C2=A0 = id3 text,
=C2=A0 =C2=A0 id4 text,<= /div>
=C2=A0 =C2=A0 f1 text,
=C2=A0 =C2=A0 f2 map<text, text>,
=C2=A0 =C2=A0 f3 map<text, text>,
=C2=A0 =C2=A0 created timestamp,
= =C2=A0 =C2=A0 updated timestamp,
=C2=A0 = =C2=A0 PRIMARY KEY (id1, id2, id3, id4)
)= WITH CLUSTERING ORDER BY (id2 ASC, id3 ASC, id4 ASC)
=C2=A0 =C2=A0 AND bloom_filter_fp_chance =3D 0.01
=
=C2=A0 =C2=A0 AND caching =3D '{"keys":= "ALL", "rows_per_partition":"NONE"}'
=C2=A0 =C2=A0 AND comment =3D ''
=C2=A0 =C2=A0 AND compaction =3D {'sstabl= e_size_in_mb': '50', 'class': 'org.apache.cassandra= .db. compaction. LeveledCompactionStrategy'}
=C2=A0 =C2=A0 AND compression =3D {'sstable_compression': &= #39;org.apache.cassandra.io. compress.LZ4Compressor&= #39;}
=C2=A0 =C2=A0 AND dclocal_read_repa= ir_chance =3D 0.0
=C2=A0 =C2=A0 AND defau= lt_time_to_live =3D 0
=C2=A0 =C2=A0 AND g= c_grace_seconds =3D 864000
=C2=A0 =C2=A0 = AND max_index_interval =3D 2048
=C2=A0 = =C2=A0 AND memtable_flush_period_in_ms =3D 0
=C2=A0 =C2=A0 AND min_index_interval =3D 128
=C2=A0 =C2=A0 AND read_repair_chance =3D 0.1
=C2=A0 =C2=A0 AND speculative_retry =3D '99.0PERCENTILE'= ;;

=
and the query is=C2=A0select * from tbl where id1=3D?= and id2=3D? and id3=3D? and id4=3D?

The timeouts happen withi= n ~2s to ~5s, while the successful calls have avg of 8ms and p99 of 15s. Th= ese times are seen from app side, the actual query times would be slightly = lower.=C2=A0

Is there a way to capture traces only when querie= s take longer than a specified duration? . We can't enable tracing in p= roduction given the volume of traffic. We see that the same query which tim= ed out works fine later, so not sure if the trace of a successful run would= help.

Thanks,
Joseph=


On Wed, Aug 31, 2016 at 8:05 PM, Patrick McFadin = <pmcfadin@gmail.com> wrote:
If= you are getting a timeout on one table, then a mismatch of RF and node cou= nt doesn't seem as likely.=C2=A0

Time to look at your query. Yo= u said it was a 'select * from table where key=3D?' type query. I w= ould next use the trace facility in cqlsh to investigate further. That'= s a good way to find hard to find issues. You should be looking for clear l= edge where you go from single digit ms to 4 or 5 digit ms times.=C2=A0

The other place to look is your data model for that table if you w= ant to post the output from a desc table.

=
Patrick


=

On Tue, Aug 30, 2016 at 11:07= AM, Joseph Tech <jaalex.tech@gmail.co= m> wrote:
=
On further analysis, this issue happ= ens only on 1 table in the KS which has the max reads.=C2=A0

@Atul, = I will look at system health, but didnt see anything standing out from GC l= ogs. (using JDK 1.8_92 with G1GC).=C2=A0

@Patrick , could you please= elaborate the "mismatch on node count + RF" part.

On Tue, Aug 30, 2016 at 5:35 PM, Atul = Saroha <atul.saroha@snapdeal.com> wrote:

<= font size=3D"2">On Tue, Aug 30, 2016 at 5:10 PM, Joseph Tech <jaalex.tech@gmail.com> wrote:
Hi Patrick,

<= /div>
The nodetool status shows all nodes up and norma= l now. From OpsCenter "Event Log" , there are some nodes reported= as being down/up etc. during the timeframe of timeout, but these are Searc= h workload nodes from the remote (non-local) DC. The RF is 3 and there are = 9 nodes per DC.

Thanks,
Jose= ph

On Mon, Aug 29, 2016 at 11= :07 PM, Patrick McFadin <pmcfadin@gmail.c= om> wrote:
You aren't achieving quorum on = your reads as the error is explains. That means you either have some nodes = down or your topology is not matching up. The fact you are using LOCAL_QUOR= UM might point to a datacenter mis-match on node count + RF.=C2=A0
W= hat does your nodetool status look like?

<= /font>
Patrick

On Mon, Aug 29, 2016 at 10:14 AM, Joseph Tech <jaalex.tech@gmail.com> wrote:
Hi,

We recently started getting intermittent timeouts on prim= ary key queries (select * from table where key=3D<key>)
<= div>
The error is : com.datastax.driver.core.excep tions.ReadTimeout= Exception: Cassandra timeout during read query at consistency LOCAL_QUORUM = (2 responses were required but only 1 replica
a responded)

The same query would work fine when tried directly from cqlsh. There ar= e no indications in system.log for the table in question, though there were= compactions in progress for tables in another keyspace which is more frequ= ently accessed.=C2=A0

My understanding is that the chanc= es of primary key queries timing out is very minimal. Please share the poss= ible reasons / ways to debug this issue.=C2=A0

We are using Cassandra 2.1 (DSE 4.8.7).

Thanks,
Joseph



=





=

<= /div>


=

<= /div>





--
Regards,Anshu=C2=A0


--001a114c5e648f113c053bc60084--