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:08:09 GMT
Comments inline.

On Mon, Oct 19, 2009 at 6:33 PM, Jonathan Ellis <jbellis@gmail.com> wrote:
> On Mon, Oct 19, 2009 at 8:20 PM, Edmond Lau <edmond@ooyala.com> wrote:
>> On Mon, Oct 19, 2009 at 6:01 PM, Jonathan Ellis <jbellis@gmail.com> wrote:
>>> are there many rows like this?
>>
>> No - just a handful.  I'm able to repro by just launching 5 or 6
>> threads that all read the same key.
>
> Does it work if you just read one column? 2? 10?  If it does, how long
> do those take?

I've simplified my repro case.  No other cassandra reads/writes other
than one client sending 3 concurrent get_slice() calls to the same
node.  Each get_slice() now asks for 1 column with start and finish
set to "", and all of them target the same row I've been talking
about.  Debug logging is enabled for the node, and I've attached logs
snippets at the end of email.  All 3 reads end up failing.

>
> Is the system busy with other reads or writes?

No.

>
> What resource do you see being used on the queried nodes?  cpu? (top)
> disk? (iostat)

cpu on the node with the data and those responsible for the digests
spike up to 250-450%.  Barely any disk activity on iostat.

>
> (Turn on debug logging to see which nodes are getting the queries, if
> necessary.)
>
>> I did find one point of note though.  Most of the quorum reads fail
>> with 0 or 1 responses, but I see some that fail with 2 responses,
>> which is odd given that only 2 responses were needed:
>
> That means it got an answer from the 2 nodes computing hashes of the
> answer for quorum purposes, but not the node that was tasked with
> retrieving the actual data.

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?

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.

DEBUG [pool-1-thread-48] 2009-10-20 01:56:38,258 CassandraServer.java
(line 219) get_slice
DEBUG [pool-1-thread-48] 2009-10-20 01:56:38,260 StorageProxy.java
(line 374) strongread reading data for
SliceFromReadCommand(table='Analytics', key='o:movie',
column_parent='QueryPath(columnFamilyName='movie',
superColumnName='[B@68eda583', columnName='null')', start='',
finish='', reversed=false, count=1) from 5613@172.16.129.71:7000
DEBUG [pool-1-thread-48] 2009-10-20 01:56:38,285 StorageProxy.java
(line 381) strongread reading digest for
SliceFromReadCommand(table='Analytics', key='o:movie',
column_parent='QueryPath(columnFamilyName='movie',
superColumnName='[B@68eda583', columnName='null')', start='',
finish='', reversed=false, count=1) from 5614@172.16.129.75:7000
DEBUG [pool-1-thread-48] 2009-10-20 01:56:38,286 StorageProxy.java
(line 381) strongread reading digest for
SliceFromReadCommand(table='Analytics', key='o:movie',
column_parent='QueryPath(columnFamilyName='movie',
superColumnName='[B@68eda583', columnName='null')', start='',
finish='', reversed=false, count=1) from 5614@172.16.129.72:7000
DEBUG [pool-1-thread-50] 2009-10-20 01:56:38,287 CassandraServer.java
(line 219) get_slice
DEBUG [pool-1-thread-49] 2009-10-20 01:56:38,277 CassandraServer.java
(line 219) get_slice
DEBUG [pool-1-thread-50] 2009-10-20 01:56:38,289 StorageProxy.java
(line 374) strongread reading data for
SliceFromReadCommand(table='Analytics', key='o:movie',
column_parent='QueryPath(columnFamilyName='movie',
superColumnName='[B@4a0d7146', columnName='null')', start='',
finish='', reversed=false, count=1) from 5615@172.16.129.71:7000
DEBUG [pool-1-thread-50] 2009-10-20 01:56:38,290 StorageProxy.java
(line 381) strongread reading digest for
SliceFromReadCommand(table='Analytics', key='o:movie',
column_parent='QueryPath(columnFamilyName='movie',
superColumnName='[B@4a0d7146', columnName='null')', start='',
finish='', reversed=false, count=1) from 5616@172.16.129.75:7000
DEBUG [pool-1-thread-49] 2009-10-20 01:56:38,291 StorageProxy.java
(line 374) strongread reading data for
SliceFromReadCommand(table='Analytics', key='o:movie',
column_parent='QueryPath(columnFamilyName='movie',
superColumnName='[B@5c931da1', columnName='null')', start='',
finish='', reversed=false, count=1) from 5617@172.16.129.71:7000
DEBUG [pool-1-thread-50] 2009-10-20 01:56:38,291 StorageProxy.java
(line 381) strongread reading digest for
SliceFromReadCommand(table='Analytics', key='o:movie',
column_parent='QueryPath(columnFamilyName='movie',
superColumnName='[B@4a0d7146', columnName='null')', start='',
finish='', reversed=false, count=1) from 5616@172.16.129.72:7000
DEBUG [pool-1-thread-49] 2009-10-20 01:56:38,291 StorageProxy.java
(line 381) strongread reading digest for
SliceFromReadCommand(table='Analytics', key='o:movie',
column_parent='QueryPath(columnFamilyName='movie',
superColumnName='[B@5c931da1', columnName='null')', start='',
finish='', reversed=false, count=1) from 5618@172.16.129.75:7000
DEBUG [pool-1-thread-49] 2009-10-20 01:56:38,292 StorageProxy.java
(line 381) strongread reading digest for
SliceFromReadCommand(table='Analytics', key='o:movie',
column_parent='QueryPath(columnFamilyName='movie',
superColumnName='[B@5c931da1', columnName='null')', start='',
finish='', reversed=false, count=1) from 5618@172.16.129.72:7000
ERROR [pool-1-thread-50] 2009-10-20 01:56:43,296 Cassandra.java (line
679) Internal error processing get_slice
java.lang.RuntimeException: java.util.concurrent.TimeoutException:
Operation timed out - received only 0 responses from  .
        at org.apache.cassandra.service.CassandraServer.readColumnFamily(CassandraServer.java:108)
        at org.apache.cassandra.service.CassandraServer.getSlice(CassandraServer.java:182)
        at org.apache.cassandra.service.CassandraServer.multigetSliceInternal(CassandraServer.java:251)
        at org.apache.cassandra.service.CassandraServer.get_slice(CassandraServer.java:220)
        at org.apache.cassandra.service.Cassandra$Processor$get_slice.process(Cassandra.java:671)
        at org.apache.cassandra.service.Cassandra$Processor.process(Cassandra.java:627)
        at org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:253)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:619)
Caused by: java.util.concurrent.TimeoutException: Operation timed out
- received only 0 responses from  .
        at org.apache.cassandra.service.QuorumResponseHandler.get(QuorumResponseHandler.java:88)
        at org.apache.cassandra.service.StorageProxy.strongRead(StorageProxy.java:395)
        at org.apache.cassandra.service.StorageProxy.readProtocol(StorageProxy.java:317)
        at org.apache.cassandra.service.CassandraServer.readColumnFamily(CassandraServer.java:100)
        ... 9 more
ERROR [pool-1-thread-49] 2009-10-20 01:56:43,296 Cassandra.java (line
679) Internal error processing get_slice
java.lang.RuntimeException: java.util.concurrent.TimeoutException:
Operation timed out - received only 0 responses from  .
        at org.apache.cassandra.service.CassandraServer.readColumnFamily(CassandraServer.java:108)
        at org.apache.cassandra.service.CassandraServer.getSlice(CassandraServer.java:182)
        at org.apache.cassandra.service.CassandraServer.multigetSliceInternal(CassandraServer.java:251)
        at org.apache.cassandra.service.CassandraServer.get_slice(CassandraServer.java:220)
        at org.apache.cassandra.service.Cassandra$Processor$get_slice.process(Cassandra.java:671)
        at org.apache.cassandra.service.Cassandra$Processor.process(Cassandra.java:627)
        at org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:253)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:619)
Caused by: java.util.concurrent.TimeoutException: Operation timed out
- received only 0 responses from  .
        at org.apache.cassandra.service.QuorumResponseHandler.get(QuorumResponseHandler.java:88)
        at org.apache.cassandra.service.StorageProxy.strongRead(StorageProxy.java:395)
        at org.apache.cassandra.service.StorageProxy.readProtocol(StorageProxy.java:317)
        at org.apache.cassandra.service.CassandraServer.readColumnFamily(CassandraServer.java:100)
        ... 9 more
ERROR [pool-1-thread-48] 2009-10-20 01:56:43,325 Cassandra.java (line
679) Internal error processing get_slice
java.lang.RuntimeException: java.util.concurrent.TimeoutException:
Operation timed out - received only 0 responses from  .
        at org.apache.cassandra.service.CassandraServer.readColumnFamily(CassandraServer.java:108)
        at org.apache.cassandra.service.CassandraServer.getSlice(CassandraServer.java:182)
        at org.apache.cassandra.service.CassandraServer.multigetSliceInternal(CassandraServer.java:251)
        at org.apache.cassandra.service.CassandraServer.get_slice(CassandraServer.java:220)
        at org.apache.cassandra.service.Cassandra$Processor$get_slice.process(Cassandra.java:671)
        at org.apache.cassandra.service.Cassandra$Processor.process(Cassandra.java:627)
        at org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:253)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:619)
Caused by: java.util.concurrent.TimeoutException: Operation timed out
- received only 0 responses from  .
        at org.apache.cassandra.service.QuorumResponseHandler.get(QuorumResponseHandler.java:88)
        at org.apache.cassandra.service.StorageProxy.strongRead(StorageProxy.java:395)
        at org.apache.cassandra.service.StorageProxy.readProtocol(StorageProxy.java:317)
        at org.apache.cassandra.service.CassandraServer.readColumnFamily(CassandraServer.java:100)
        ... 9 more
DEBUG [ROW-READ-STAGE:2] 2009-10-20 01:56:44,365 SliceQueryFilter.java
(line 115) collecting 1000002:false:592@1255996277427491
DEBUG [ROW-READ-STAGE:2] 2009-10-20 01:56:44,366 ReadVerbHandler.java
(line 100) Read key o:movie; sending response to
20CFAD41-BB15-EDF4-FC0F-CD2E5DE3B7B0@172.16.129.71:7000
DEBUG [RESPONSE-STAGE:4] 2009-10-20 01:56:44,366
ResponseVerbHandler.java (line 34) Processing response on a callback
from 20CFAD41-BB15-EDF4-FC0F-CD2E5DE3B7B0@172.16.129.71:7000
DEBUG [RESPONSE-STAGE:1] 2009-10-20 01:56:44,896
ResponseVerbHandler.java (line 34) Processing response on a callback
from 20CFAD41-BB15-EDF4-FC0F-CD2E5DE3B7B0@172.16.129.72:7000
DEBUG [ROW-READ-STAGE:3] 2009-10-20 01:56:44,903 SliceQueryFilter.java
(line 115) collecting 1000002:false:592@1255996277427491
DEBUG [ROW-READ-STAGE:3] 2009-10-20 01:56:44,904 ReadVerbHandler.java
(line 100) Read key o:movie; sending response to
8FAC5892-1A6D-7948-9F9F-EAE5D570F10F@172.16.129.71:7000
DEBUG [RESPONSE-STAGE:2] 2009-10-20 01:56:44,904
ResponseVerbHandler.java (line 34) Processing response on a callback
from 8FAC5892-1A6D-7948-9F9F-EAE5D570F10F@172.16.129.71:7000
DEBUG [RESPONSE-STAGE:3] 2009-10-20 01:56:44,976
ResponseVerbHandler.java (line 34) Processing response on a callback
from B7129ABF-B49D-F5E9-4E0A-CD2F46FEC31A@172.16.129.72:7000
DEBUG [RESPONSE-STAGE:4] 2009-10-20 01:56:45,150
ResponseVerbHandler.java (line 34) Processing response on a callback
from 8FAC5892-1A6D-7948-9F9F-EAE5D570F10F@172.16.129.72:7000
DEBUG [ROW-READ-STAGE:4] 2009-10-20 01:56:45,283 SliceQueryFilter.java
(line 115) collecting 1000002:false:592@1255996277427491
DEBUG [ROW-READ-STAGE:4] 2009-10-20 01:56:45,284 ReadVerbHandler.java
(line 100) Read key o:movie; sending response to
B7129ABF-B49D-F5E9-4E0A-CD2F46FEC31A@172.16.129.71:7000
DEBUG [RESPONSE-STAGE:1] 2009-10-20 01:56:45,284
ResponseVerbHandler.java (line 34) Processing response on a callback
from B7129ABF-B49D-F5E9-4E0A-CD2F46FEC31A@172.16.129.71:7000
DEBUG [RESPONSE-STAGE:2] 2009-10-20 01:56:45,371
ResponseVerbHandler.java (line 34) Processing response on a callback
from B7129ABF-B49D-F5E9-4E0A-CD2F46FEC31A@172.16.129.75:7000
DEBUG [RESPONSE-STAGE:3] 2009-10-20 01:56:45,800
ResponseVerbHandler.java (line 34) Processing response on a callback
from 8FAC5892-1A6D-7948-9F9F-EAE5D570F10F@172.16.129.75:7000
DEBUG [RESPONSE-STAGE:4] 2009-10-20 01:56:46,005
ResponseVerbHandler.java (line 34) Processing response on a callback
from 20CFAD41-BB15-EDF4-FC0F-CD2E5DE3B7B0@172.16.129.75:7000

Edmond

>
> -Jonathan
>

Mime
View raw message