The optimization definitely shaved off some time. Now it is running about 3x CFSTATS reported time. Below are the logs.

There is a ~300ms time frame after the last ResponseVerbHandler prior to the resolver starting. Based on a quorum read the response resolver should kick after 2 reads come in correct? That would mean it waited 500ms before starting. Where is this time going?

There is still the 3+ second delay between the last 2 entries. Is this the thrift server?

My expectation is that the client should get a quorum read at 2nd fastest CFSTATS reported time x 1.xx. It should take the most time to read the data from the node and after that it is all in memory and just needs to be processed. There are some gaps in the timing of the cassandra qurum reader below, but the lowest hanging fruit seems to be what happens between quorumResponseHandler & "logout complete". Excluding that last step node 208 (2nd fastest) reported 2027ms in cfstats which as a % of 3320 ms = 1.63x.


DEBUG [pool-1-thread-2] 2010-10-15 18:59:34,894 CassandraServer.java (line 216) get_slice
DEBUG [pool-1-thread-2] 2010-10-15 18:59:34,895 StorageProxy.java (line 471) strongread reading data for SliceFromReadCommand(table='table', key='key1', column_parent='QueryPath(columnFamilyName='fact', superColumnName='null', columnName='null')', start='503a', finish='503a7c', reversed=false, count=10000000) from 385@/x.x.x.6
DEBUG [pool-1-thread-2] 2010-10-15 18:59:34,895 StorageProxy.java (line 471) strongread reading digest for SliceFromReadCommand(table='table', key='key1', column_parent='QueryPath(columnFamilyName='fact', superColumnName='null', columnName='null')', start='503a', finish='503a7c', reversed=false, count=10000000) from 386@/x.x.x.7
DEBUG [pool-1-thread-2] 2010-10-15 18:59:34,896 StorageProxy.java (line 471) strongread reading digest for SliceFromReadCommand(table='table', key='key1', column_parent='QueryPath(columnFamilyName='fact', superColumnName='null', columnName='null')', start='503a', finish='503a7c', reversed=false, count=10000000) from 386@/x.x.x.8
DEBUG [RESPONSE-STAGE:4] 2010-10-15 18:59:36,824 ResponseVerbHandler.java (line 42) Processing response on a callback from 2DDDC24C-DB98-1D0F-E945-1DBF8EA99248@/10.4.0.206
DEBUG [RESPONSE-STAGE:5] 2010-10-15 18:59:37,115 ResponseVerbHandler.java (line 42) Processing response on a callback from 2DDDC24C-DB98-1D0F-E945-1DBF8EA99248@/10.4.0.208
DEBUG [RESPONSE-STAGE:6] 2010-10-15 18:59:37,302 ResponseVerbHandler.java (line 42) Processing response on a callback from 2DDDC24C-DB98-1D0F-E945-1DBF8EA99248@/10.4.0.207
DEBUG [pool-1-thread-2] 2010-10-15 18:59:37,585 ReadResponseResolver.java (line 72) resolving 3 responses
DEBUG [pool-1-thread-2] 2010-10-15 18:59:38,065 ReadResponseResolver.java (line 106) responses deserialized
DEBUG [pool-1-thread-2] 2010-10-15 18:59:38,216 ReadResponseResolver.java (line 122) digests verified
DEBUG [pool-1-thread-2] 2010-10-15 18:59:38,216 ReadResponseResolver.java (line 139) resolve: 630 ms.
DEBUG [pool-1-thread-2] 2010-10-15 18:59:38,217 StorageProxy.java (line 494) quorumResponseHandler: 3320 ms.
DEBUG [pool-1-thread-2] 2010-10-15 18:59:41,556 CassandraServer.java (line 664) logout complete


On Thu, Oct 14, 2010 at 7:16 PM, Jonathan Ellis <jbellis@gmail.com> wrote:
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 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



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