incubator-cassandra-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Edmond Lau <edm...@ooyala.com>
Subject Re: repeated timeouts on quorum reads
Date Tue, 20 Oct 2009 02:48:30 GMT
On Mon, Oct 19, 2009 at 7:23 PM, Jonathan Ellis <jbellis@gmail.com> wrote:
> On Mon, Oct 19, 2009 at 9:08 PM, Edmond Lau <edmond@ooyala.com> wrote:
>> Why do we need 2 nodes to compute hashes in addition to another node
>> for retrieving the data?  Then the system is reading all three copies
>> instead of just a quorum of 2.  Why not just one node for a hash and
>> one node for hash + data?
>
> That way you can take whichever hash finishes first.

Ah.

>
>> Here are my debug logs from the node with 3 concurrent reads.  5
>> seconds after the get_slice, the rpc times out.  3 seconds after the
>> timeout, all the callbacks return.  I know that the entire supercolumn
>> (~15MB) has to be read into memory, but 8 seconds for 3 reads seems
>> extremely slow.
>
> I agree.
>
> A couple more questions:
>
> How many data files are there across all the directories (on a single
> node) for the CF in question?
>

8 data files total.  3 nodes have 1, 1 has 2, the 3rd has 3.

> Does it still take ~8s if you direct a CL.ONE query at one of the
> nodes you know has the data (i.e., a local read)?

Local reads return quickly, but if you look at the logs below, there's
6 secs from when cassandra prints that it's reading a consistency
digest to when it processes a callback.

DEBUG [pool-1-thread-58] 2009-10-20 02:36:19,780 CassandraServer.java
(line 219) get_slice
DEBUG [pool-1-thread-58] 2009-10-20 02:36:19,781 StorageProxy.java
(line 468) weakreadlocal reading
SliceFromReadCommand(table='Analytics', key='o:movie',
column_parent='QueryPath(columnFamilyName='movie',
superColumnName='[B@7ac0e349', columnName='null')', start='',
finish='', reversed=false, count=1)
DEBUG [pool-1-thread-59] 2009-10-20 02:36:19,789 CassandraServer.java
(line 219) get_slice
DEBUG [pool-1-thread-59] 2009-10-20 02:36:19,790 StorageProxy.java
(line 468) weakreadlocal reading
SliceFromReadCommand(table='Analytics', key='o:movie',
column_parent='QueryPath(columnFamilyName='movie',
superColumnName='[B@d8a0c95', columnName='null')', start='',
finish='', reversed=false, count=1)
DEBUG [pool-1-thread-60] 2009-10-20 02:36:19,798 CassandraServer.java
(line 219) get_slice
DEBUG [pool-1-thread-60] 2009-10-20 02:36:19,800 StorageProxy.java
(line 468) weakreadlocal reading
SliceFromReadCommand(table='Analytics', key='o:movie',
column_parent='QueryPath(columnFamilyName='movie',
superColumnName='[B@62401124', columnName='null')', start='',
finish='', reversed=false, count=1)
DEBUG [pool-1-thread-59] 2009-10-20 02:36:24,842 SliceQueryFilter.java
(line 115) collecting 1000002:false:592@1255996277427491
DEBUG [CONSISTENCY-MANAGER:4] 2009-10-20 02:36:24,843
ConsistencyManager.java (line 168) Reading consistency digest for
o:movie from 14629@[172.16.129.75:7000, 172.16.129.72:7000]
DEBUG [pool-1-thread-58] 2009-10-20 02:36:25,319 SliceQueryFilter.java
(line 115) collecting 1000002:false:592@1255996277427491
DEBUG [CONSISTENCY-MANAGER:1] 2009-10-20 02:36:25,324
ConsistencyManager.java (line 168) Reading consistency digest for
o:movie from 14632@[172.16.129.75:7000, 172.16.129.72:7000]
DEBUG [pool-1-thread-60] 2009-10-20 02:36:25,327 SliceQueryFilter.java
(line 115) collecting 1000002:false:592@1255996277427491
DEBUG [CONSISTENCY-MANAGER:2] 2009-10-20 02:36:25,328
ConsistencyManager.java (line 168) Reading consistency digest for
o:movie from 14633@[172.16.129.75:7000, 172.16.129.72:7000]
DEBUG [RESPONSE-STAGE:3] 2009-10-20 02:36:31,501
ResponseVerbHandler.java (line 34) Processing response on a callback
from 14629@172.16.129.72:7000
DEBUG [RESPONSE-STAGE:4] 2009-10-20 02:36:31,541
ResponseVerbHandler.java (line 34) Processing response on a callback
from 14633@172.16.129.72:7000
DEBUG [RESPONSE-STAGE:1] 2009-10-20 02:36:31,610
ResponseVerbHandler.java (line 34) Processing response on a callback
from 14632@172.16.129.72:7000
DEBUG [RESPONSE-STAGE:2] 2009-10-20 02:36:31,711
ResponseVerbHandler.java (line 34) Processing response on a callback
from 14629@172.16.129.75:7000
DEBUG [RESPONSE-STAGE:2] 2009-10-20 02:36:31,713
ConsistencyManager.java (line 96) Performing read repair for o:movie
to 14653@[172.16.129.75:7000, 172.16.129.72:7000, 172.16.129.71:7000]
DEBUG [RESPONSE-STAGE:3] 2009-10-20 02:36:32,326
ResponseVerbHandler.java (line 34) Processing response on a callback
from 14633@172.16.129.75:7000
DEBUG [RESPONSE-STAGE:3] 2009-10-20 02:36:32,328
ConsistencyManager.java (line 96) Performing read repair for o:movie
to 14657@[172.16.129.75:7000, 172.16.129.72:7000, 172.16.129.71:7000]
DEBUG [RESPONSE-STAGE:4] 2009-10-20 02:36:34,024
ResponseVerbHandler.java (line 34) Processing response on a callback
from 14632@172.16.129.75:7000
DEBUG [RESPONSE-STAGE:4] 2009-10-20 02:36:34,026
ConsistencyManager.java (line 96) Performing read repair for o:movie
to 14665@[172.16.129.75:7000, 172.16.129.72:7000, 172.16.129.71:7000]
DEBUG [RESPONSE-STAGE:1] 2009-10-20 02:36:37,082
ResponseVerbHandler.java (line 34) Processing response on a callback
from 14653@172.16.129.72:7000
DEBUG [RESPONSE-STAGE:1] 2009-10-20 02:36:37,083
ConsistencyManager.java (line 116) Received responses in
DataRepairHandler : ID:14653
FROM:172.16.129.72:7000
TYPE:RESPONSE-STAGE
VERB:RESPONSE

DEBUG [ROW-READ-STAGE:13] 2009-10-20 02:36:37,119
SliceQueryFilter.java (line 115) collecting
1000002:false:592@1255996277427491
DEBUG [ROW-READ-STAGE:13] 2009-10-20 02:36:37,119 ReadVerbHandler.java
(line 100) Read key o:movie; sending response to
14653@172.16.129.71:7000
DEBUG [RESPONSE-STAGE:2] 2009-10-20 02:36:37,162
ResponseVerbHandler.java (line 34) Processing response on a callback
from 14653@172.16.129.71:7000
DEBUG [RESPONSE-STAGE:2] 2009-10-20 02:36:37,163
ConsistencyManager.java (line 116) Received responses in
DataRepairHandler : ID:14653
FROM:172.16.129.71:7000
TYPE:RESPONSE-STAGE
VERB:RESPONSE

DEBUG [RESPONSE-STAGE:3] 2009-10-20 02:36:37,415
ResponseVerbHandler.java (line 34) Processing response on a callback
from 14657@172.16.129.72:7000
DEBUG [RESPONSE-STAGE:3] 2009-10-20 02:36:37,416
ConsistencyManager.java (line 116) Received responses in
DataRepairHandler : ID:14657
FROM:172.16.129.72:7000
TYPE:RESPONSE-STAGE
VERB:RESPONSE

DEBUG [CACHETABLE-TIMER-4] 2009-10-20 02:36:37,992
ReadResponseResolver.java (line 84) Response deserialization time : 0
ms.
DEBUG [CACHETABLE-TIMER-4] 2009-10-20 02:36:37,993
ReadResponseResolver.java (line 84) Response deserialization time : 0
ms.
DEBUG [CACHETABLE-TIMER-4] 2009-10-20 02:36:37,994
ReadResponseResolver.java (line 149) resolve: 2 ms.
DEBUG [ROW-READ-STAGE:15] 2009-10-20 02:36:38,051
SliceQueryFilter.java (line 115) collecting
1000002:false:592@1255996277427491
DEBUG [ROW-READ-STAGE:15] 2009-10-20 02:36:38,052 ReadVerbHandler.java
(line 100) Read key o:movie; sending response to
14665@172.16.129.71:7000
DEBUG [RESPONSE-STAGE:4] 2009-10-20 02:36:38,052
ResponseVerbHandler.java (line 34) Processing response on a callback
from 14665@172.16.129.71:7000
DEBUG [RESPONSE-STAGE:4] 2009-10-20 02:36:38,053
ConsistencyManager.java (line 116) Received responses in
DataRepairHandler : ID:14665
FROM:172.16.129.71:7000
TYPE:RESPONSE-STAGE
VERB:RESPONSE

DEBUG [ROW-READ-STAGE:17] 2009-10-20 02:36:38,146
SliceQueryFilter.java (line 115) collecting
1000002:false:592@1255996277427491
DEBUG [ROW-READ-STAGE:17] 2009-10-20 02:36:38,146 ReadVerbHandler.java
(line 100) Read key o:movie; sending response to
14657@172.16.129.71:7000
DEBUG [RESPONSE-STAGE:1] 2009-10-20 02:36:38,146
ResponseVerbHandler.java (line 34) Processing response on a callback
from 14657@172.16.129.71:7000
DEBUG [RESPONSE-STAGE:1] 2009-10-20 02:36:38,147
ConsistencyManager.java (line 116) Received responses in
DataRepairHandler : ID:14657
FROM:172.16.129.71:7000
TYPE:RESPONSE-STAGE
VERB:RESPONSE

DEBUG [RESPONSE-STAGE:2] 2009-10-20 02:36:38,957
ResponseVerbHandler.java (line 34) Processing response on a callback
from 14665@172.16.129.72:7000
DEBUG [RESPONSE-STAGE:2] 2009-10-20 02:36:38,958
ConsistencyManager.java (line 116) Received responses in
DataRepairHandler : ID:14665
FROM:172.16.129.72:7000
TYPE:RESPONSE-STAGE
VERB:RESPONSE

DEBUG [CACHETABLE-TIMER-4] 2009-10-20 02:36:39,193
ReadResponseResolver.java (line 84) Response deserialization time : 0
ms.
DEBUG [CACHETABLE-TIMER-4] 2009-10-20 02:36:39,194
ReadResponseResolver.java (line 84) Response deserialization time : 0
ms.
DEBUG [CACHETABLE-TIMER-4] 2009-10-20 02:36:39,194
ReadResponseResolver.java (line 149) resolve: 1 ms.
DEBUG [CACHETABLE-TIMER-4] 2009-10-20 02:36:39,792
ReadResponseResolver.java (line 84) Response deserialization time : 0
ms.
DEBUG [CACHETABLE-TIMER-4] 2009-10-20 02:36:39,793
ReadResponseResolver.java (line 84) Response deserialization time : 0
ms.
DEBUG [CACHETABLE-TIMER-4] 2009-10-20 02:36:39,793
ReadResponseResolver.java (line 149) resolve: 1 ms.
DEBUG [RESPONSE-STAGE:3] 2009-10-20 02:36:40,294
ResponseVerbHandler.java (line 34) Processing response on a callback
from 14657@172.16.129.75:7000
DEBUG [RESPONSE-STAGE:3] 2009-10-20 02:36:40,295
ConsistencyManager.java (line 116) Received responses in
DataRepairHandler : ID:14657
FROM:172.16.129.75:7000
TYPE:RESPONSE-STAGE
VERB:RESPONSE

DEBUG [RESPONSE-STAGE:4] 2009-10-20 02:36:40,357
ResponseVerbHandler.java (line 34) Processing response on a callback
from 14653@172.16.129.75:7000
DEBUG [RESPONSE-STAGE:4] 2009-10-20 02:36:40,358
ConsistencyManager.java (line 116) Received responses in
DataRepairHandler : ID:14653
FROM:172.16.129.75:7000
TYPE:RESPONSE-STAGE
VERB:RESPONSE

DEBUG [RESPONSE-STAGE:1] 2009-10-20 02:36:41,208
ResponseVerbHandler.java (line 34) Processing response on a callback
from 14665@172.16.129.75:7000
DEBUG [RESPONSE-STAGE:1] 2009-10-20 02:36:41,209
ConsistencyManager.java (line 116) Received responses in
DataRepairHandler : ID:14665
FROM:172.16.129.75:7000
TYPE:RESPONSE-STAGE
VERB:RESPONSE

>
> What does JConsole show about jvm memory usage during the query?  Is
> it right up against the heap size limit?
>

jvm heap memory usage goes from 50MB to < 200MB.  Nothing major.


Edmond

Mime
View raw message