cassandra-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Wayne <wav...@gmail.com>
Subject Read Latency
Date Thu, 14 Oct 2010 20:18:16 GMT
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 back
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 data
for almost 10 seconds seconds. Where is the other 7+ seconds going? We are
using 0.6.5 with rf=3.

We have verified that the difference between get_slice and "logout complete"
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 than
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 of
Cassandra. Why does it take another 3+ seconds to get it to the client? Is
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 (line
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='xx',
key='row_key', column_parent='QueryPath(columnFamilyName='fact',
superColumnName='null', columnName='null')', start='503a', finish='503a7c',
reversed=false, count=10000000) 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='xx',
key='row_key', column_parent='QueryPath(columnFamilyName='fact',
superColumnName='null', columnName='null')', start='503a', finish='503a7c',
reversed=false, count=10000000) 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='xx',
key='row_key', column_parent='QueryPath(columnFamilyName='fact',
superColumnName='null', columnName='null')', start='503a', finish='503a7c',
reversed=false, count=10000000) from 7953@/x.x.x.8
DEBUG [RESPONSE-STAGE:15] 2010-10-14 19:26:19,090 ResponseVerbHandler.java
(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.java
(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
 INFO [GC inspection] 2010-10-14 19:26:20,780 GCInspector.java (line 129) 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.java
(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 (line
664) logout complete

Mime
View raw message