Mailing-List: contact user-help@cassandra.apache.org; run by ezmlm
Precedence: bulk
Reply-To: user@cassandra.apache.org
Received-SPF: pass (nike.apache.org: domain of jbellis@gmail.com designates
 74.125.82.172 as permitted sender)
DomainKey-Signature: a=rsa-sha1; c=nofws;
        d=gmail.com; s=gamma;
        h=mime-version:in-reply-to:references:date:message-id:subject:from:to
         :content-type;
        b=YF3MRdsp67NLh7H1Stw9W+uXxqAONdCfCQel3l4Hf4Gc1vqwr/tX6vOF2TafIHiwlS
         j5StcleV/Xsuo46fjSHF1B+b6SQbtbMUBMhvOlQlx5kEUQWt0lb2Vj2sF/efQj1JWGBw
         Z1Jy79tYMjBoJn02mZCMgJXcxzEognMINZoNk=
MIME-Version: 1.0
In-Reply-To: <AANLkTinebvQREj9gB9_Fb8nU0Z-T-MMas5ewqyxDJ8h2@mail.gmail.com>
References: <AANLkTinebvQREj9gB9_Fb8nU0Z-T-MMas5ewqyxDJ8h2@mail.gmail.com>
Date: Thu, 14 Oct 2010 18:16:34 -0500
Message-ID: <AANLkTimQTVMg0_t+d_2f9Acxgb5vnvzLHPdT=Q7e8MGM@mail.gmail.com>
Subject: Re: Read Latency
From: Jonathan Ellis <jbellis@gmail.com>
To: user <user@cassandra.apache.org>
Content-Type: multipart/mixed; boundary=00151757415eb12c6804929be627

--00151757415eb12c6804929be627
Content-Type: text/plain; charset=ISO-8859-1
Content-Transfer-Encoding: quoted-printable

I bet it's the deserializing of responses into Row objects that is
taking most of the time.  (This would also fit the resolve time
growing proportionately with the cfstats time -- larger results take
longer to serialize/deserialize.)

Attached is a patch that adds extra debug information to verify this.
If you can apply it (patch -p0 < resolve.txt against 0.6.6, should
also work against 0.6.5) and let us know the results, that would be
great.

It also adds an optimization to avoid cloning the result in the common
case where digests match (which is the case in your logs, or you would
see "digest mismatch" at debug level).

On Thu, Oct 14, 2010 at 3:18 PM, Wayne <wav100@gmail.com> wrote:
> Can someone help to determine the anatomy of a quorum read? We are trying=
 to
> understand why CFSTATS reports one time and the client actual gets data b=
ack
> almost 4x slower. Below are the debug logs from a read that all 3 nodes
> reported < 2.5secs response time in cfstats but the client did not get da=
ta
> for almost 10 seconds seconds. Where is the other 7+ seconds going? We ar=
e
> using 0.6.5 with rf=3D3.
>
> We have verified that the difference between get_slice and "logout comple=
te"
> is the actual client wait time.
>
> The slowest node to respond returned data at 19:26:19,303. That is 2.618
> seconds. CFSTATS reports a faster time by a few hundred nanoseconds, and =
I
> assume the difference is network latency?
>
> Why does ReadResponseResolver take almost 3 seconds? That is longer that
> actually doing the read. This is a wide row, does this prove Cassandra is
> not very efficient reading wide rows at least in 0.6.5? Does this prove a
> quorum read is more expensive in terms of making sure the copies match th=
an
> it is to actually read the data (not good news for those of us that often
> need the C in CAP)?
>
> Why is the time stamp for the ReadResponseResolver more than 3.5 seconds
> after the last read came in when it says it took less than three seconds =
for
> the resolver? Where did the other 500ms go?
>
> I assume the quorumResponseHandler time is the total read time in terms o=
f
> Cassandra. Why does it take another 3+ seconds to get it to the client? I=
s
> this the thrift server? Some of the time is probably for network latency,
> but not anything close to 3 seconds. The "logout complete" time is the
> actual time the client got the data.
>
> Any help trying to map out exactly what is going on would be much
> appreciated.
>
> Thanks.
>
>
> DEBUG [pool-1-thread-11] 2010-10-14 19:26:16,684 CassandraServer.java (li=
ne
> 216) get_slice
> DEBUG [pool-1-thread-11] 2010-10-14 19:26:16,684 StorageProxy.java (line
> 474) strongread reading data for SliceFromReadCommand(table=3D'xx',
> key=3D'row_key', column_parent=3D'QueryPath(columnFamilyName=3D'fact',
> superColumnName=3D'null', columnName=3D'null')', start=3D'503a', finish=
=3D'503a7c',
> reversed=3Dfalse, count=3D10000000) from 7952@/x.x.x.6
> DEBUG [pool-1-thread-11] 2010-10-14 19:26:16,685 StorageProxy.java (line
> 474) strongread reading digest for SliceFromReadCommand(table=3D'xx',
> key=3D'row_key', column_parent=3D'QueryPath(columnFamilyName=3D'fact',
> superColumnName=3D'null', columnName=3D'null')', start=3D'503a', finish=
=3D'503a7c',
> reversed=3Dfalse, count=3D10000000) from 7953@/x.x.x.7
> DEBUG [pool-1-thread-11] 2010-10-14 19:26:16,685 StorageProxy.java (line
> 474) strongread reading digest for SliceFromReadCommand(table=3D'xx',
> key=3D'row_key', column_parent=3D'QueryPath(columnFamilyName=3D'fact',
> superColumnName=3D'null', columnName=3D'null')', start=3D'503a', finish=
=3D'503a7c',
> reversed=3Dfalse, count=3D10000000) from 7953@/x.x.x.8
> DEBUG [RESPONSE-STAGE:15] 2010-10-14 19:26:19,090 ResponseVerbHandler.jav=
a
> (line 42) Processing response on a callback from
> 7EBDA5E1-AB56-EA3C-82C4-25F0F7260468@/x.x.x.8
> DEBUG [RESPONSE-STAGE:16] 2010-10-14 19:26:19,224 ResponseVerbHandler.jav=
a
> (line 42) Processing response on a callback from
> 7EBDA5E1-AB56-EA3C-82C4-25F0F7260468@/x.x.x.6
> DEBUG [RESPONSE-STAGE:1] 2010-10-14 19:26:19,303 ResponseVerbHandler.java
> (line 42) Processing response on a callback from
> 7EBDA5E1-AB56-EA3C-82C4-25F0F7260468@/x.x.x.7
> DEBUG [GC inspection] 2010-10-14 19:26:19,776 GCInspector.java (line 131)=
 GC
> for ParNew: 96 ms, 168972776 reclaimed leaving 1165922488 used; max is
> 12995002368
> =A0INFO [GC inspection] 2010-10-14 19:26:20,780 GCInspector.java (line 12=
9) GC
> for ParNew: 373 ms, 56806184 reclaimed leaving 1336001936 used; max is
> 12995002368
> DEBUG [pool-1-thread-11] 2010-10-14 19:26:22,748 ReadResponseResolver.jav=
a
> (line 120) resolve: 2966 ms.
> DEBUG [pool-1-thread-11] 2010-10-14 19:26:22,748 StorageProxy.java (line
> 497) quorumResponseHandler: 6063 ms.
> DEBUG [pool-1-thread-11] 2010-10-14 19:26:25,983 CassandraServer.java (li=
ne
> 664) logout complete


--=20
Jonathan Ellis
Project Chair, Apache Cassandra
co-founder of Riptano, the source for professional Cassandra support
http://riptano.com

--00151757415eb12c6804929be627
Content-Type: text/plain; charset=US-ASCII; name="resolve.txt"
Content-Disposition: attachment; filename="resolve.txt"
Content-Transfer-Encoding: base64
X-Attachment-Id: f_gfa8w1ol0

SW5kZXg6IHNyYy9qYXZhL29yZy9hcGFjaGUvY2Fzc2FuZHJhL3NlcnZpY2UvUmVhZFJlc3BvbnNl
UmVzb2x2ZXIuamF2YQo9PT09PT09PT09PT09PT09PT09PT09PT09PT09PT09PT09PT09PT09PT09
PT09PT09PT09PT09PT09PT09PT09PT09Ci0tLSBzcmMvamF2YS9vcmcvYXBhY2hlL2Nhc3NhbmRy
YS9zZXJ2aWNlL1JlYWRSZXNwb25zZVJlc29sdmVyLmphdmEJKHJldmlzaW9uIDEwMjE0MTQpCisr
KyBzcmMvamF2YS9vcmcvYXBhY2hlL2Nhc3NhbmRyYS9zZXJ2aWNlL1JlYWRSZXNwb25zZVJlc29s
dmVyLmphdmEJKHdvcmtpbmcgY29weSkKQEAgLTY4LDYgKzY4LDkgQEAKICAgICAgICovCiAJcHVi
bGljIFJvdyByZXNvbHZlKENvbGxlY3Rpb248TWVzc2FnZT4gcmVzcG9uc2VzKSB0aHJvd3MgRGln
ZXN0TWlzbWF0Y2hFeGNlcHRpb24sIElPRXhjZXB0aW9uCiAgICAgeworICAgICAgICBpZiAobG9n
Z2VyXy5pc0RlYnVnRW5hYmxlZCgpKQorICAgICAgICAgICAgbG9nZ2VyXy5kZWJ1ZygicmVzb2x2
aW5nICIgKyByZXNwb25zZXMuc2l6ZSgpICsgIiByZXNwb25zZXMiKTsKKwogICAgICAgICBsb25n
IHN0YXJ0VGltZSA9IFN5c3RlbS5jdXJyZW50VGltZU1pbGxpcygpOwogCQlMaXN0PENvbHVtbkZh
bWlseT4gdmVyc2lvbnMgPSBuZXcgQXJyYXlMaXN0PENvbHVtbkZhbWlseT4ocmVzcG9uc2VzLnNp
emUoKSk7CiAJCUxpc3Q8SW5ldEFkZHJlc3M+IGVuZFBvaW50cyA9IG5ldyBBcnJheUxpc3Q8SW5l
dEFkZHJlc3M+KHJlc3BvbnNlcy5zaXplKCkpOwpAQCAtOTgsNyArMTAxLDExIEBACiAgICAgICAg
ICAgICAgICAga2V5ID0gcmVzdWx0LnJvdygpLmtleTsKICAgICAgICAgICAgIH0KICAgICAgICAg
fQotCQkvLyBJZiB0aGVyZSB3YXMgYSBkaWdlc3QgcXVlcnkgY29tcGFyZSBpdCB3aXRoIGFsbCB0
aGUgZGF0YSBkaWdlc3RzIAorCisgICAgICAgIGlmIChsb2dnZXJfLmlzRGVidWdFbmFibGVkKCkp
CisgICAgICAgICAgICBsb2dnZXJfLmRlYnVnKCJyZXNwb25zZXMgZGVzZXJpYWxpemVkIik7CisK
KwkJLy8gSWYgdGhlcmUgd2FzIGEgZGlnZXN0IHF1ZXJ5IGNvbXBhcmUgaXQgd2l0aCBhbGwgdGhl
IGRhdGEgZGlnZXN0cwogCQkvLyBJZiB0aGVyZSBpcyBhIG1pc21hdGNoIHRoZW4gdGhyb3cgYW4g
ZXhjZXB0aW9uIHNvIHRoYXQgcmVhZCByZXBhaXIgY2FuIGhhcHBlbi4KICAgICAgICAgaWYgKGlz
RGlnZXN0UXVlcnkpCiAgICAgICAgIHsKQEAgLTExMSwxMCArMTE4LDIyIEBACiAgICAgICAgICAg
ICAgICAgICAgIHRocm93IG5ldyBEaWdlc3RNaXNtYXRjaEV4Y2VwdGlvbihzKTsKICAgICAgICAg
ICAgICAgICB9CiAgICAgICAgICAgICB9CisgICAgICAgICAgICBpZiAobG9nZ2VyXy5pc0RlYnVn
RW5hYmxlZCgpKQorICAgICAgICAgICAgICAgIGxvZ2dlcl8uZGVidWcoImRpZ2VzdHMgdmVyaWZp
ZWQiKTsKICAgICAgICAgfQogCi0gICAgICAgIENvbHVtbkZhbWlseSByZXNvbHZlZCA9IHJlc29s
dmVTdXBlcnNldCh2ZXJzaW9ucyk7Ci0gICAgICAgIG1heWJlU2NoZWR1bGVSZXBhaXJzKHJlc29s
dmVkLCB0YWJsZSwga2V5LCB2ZXJzaW9ucywgZW5kUG9pbnRzKTsKKyAgICAgICAgQ29sdW1uRmFt
aWx5IHJlc29sdmVkOworICAgICAgICBpZiAodmVyc2lvbnMuc2l6ZSgpID4gMSkKKyAgICAgICAg
eworICAgICAgICAgICAgcmVzb2x2ZWQgPSByZXNvbHZlU3VwZXJzZXQodmVyc2lvbnMpOworICAg
ICAgICAgICAgaWYgKGxvZ2dlcl8uaXNEZWJ1Z0VuYWJsZWQoKSkKKyAgICAgICAgICAgICAgICBs
b2dnZXJfLmRlYnVnKCJ2ZXJzaW9ucyBtZXJnZWQiKTsKKyAgICAgICAgICAgIG1heWJlU2NoZWR1
bGVSZXBhaXJzKHJlc29sdmVkLCB0YWJsZSwga2V5LCB2ZXJzaW9ucywgZW5kUG9pbnRzKTsKKyAg
ICAgICAgfQorICAgICAgICBlbHNlCisgICAgICAgIHsKKyAgICAgICAgICAgIHJlc29sdmVkID0g
dmVyc2lvbnMuZ2V0KDApOworICAgICAgICB9CiAKICAgICAgICAgaWYgKGxvZ2dlcl8uaXNEZWJ1
Z0VuYWJsZWQoKSkKICAgICAgICAgICAgIGxvZ2dlcl8uZGVidWcoInJlc29sdmU6ICIgKyAoU3lz
dGVtLmN1cnJlbnRUaW1lTWlsbGlzKCkgLSBzdGFydFRpbWUpICsgIiBtcy4iKTsK
--00151757415eb12c6804929be627--