Return-Path: Delivered-To: apmail-incubator-cassandra-user-archive@minotaur.apache.org Received: (qmail 44949 invoked from network); 20 Oct 2009 01:21:05 -0000 Received: from hermes.apache.org (HELO mail.apache.org) (140.211.11.3) by minotaur.apache.org with SMTP; 20 Oct 2009 01:21:05 -0000 Received: (qmail 61598 invoked by uid 500); 20 Oct 2009 01:21:04 -0000 Delivered-To: apmail-incubator-cassandra-user-archive@incubator.apache.org Received: (qmail 61583 invoked by uid 500); 20 Oct 2009 01:21:04 -0000 Mailing-List: contact cassandra-user-help@incubator.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: cassandra-user@incubator.apache.org Delivered-To: mailing list cassandra-user@incubator.apache.org Received: (qmail 61574 invoked by uid 99); 20 Oct 2009 01:21:04 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 20 Oct 2009 01:21:04 +0000 X-ASF-Spam-Status: No, hits=-0.0 required=10.0 tests=SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (nike.apache.org: domain of edmond@ooyala.com designates 209.85.222.197 as permitted sender) Received: from [209.85.222.197] (HELO mail-pz0-f197.google.com) (209.85.222.197) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 20 Oct 2009 01:20:56 +0000 Received: by pzk35 with SMTP id 35so3944009pzk.22 for ; Mon, 19 Oct 2009 18:20:35 -0700 (PDT) MIME-Version: 1.0 Received: by 10.142.66.21 with SMTP id o21mr396485wfa.47.1256001635077; Mon, 19 Oct 2009 18:20:35 -0700 (PDT) In-Reply-To: References: From: Edmond Lau Date: Mon, 19 Oct 2009 18:20:15 -0700 Message-ID: Subject: Re: repeated timeouts on quorum reads To: cassandra-user@incubator.apache.org Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: quoted-printable X-Virus-Checked: Checked by ClamAV on apache.org On Mon, Oct 19, 2009 at 6:01 PM, Jonathan Ellis 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. > > did you check the logs on the other nodes for exceptions? Yes - no exceptions. 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: ERROR [pool-1-thread-18] 2009-10-20 01:17:26,266 Cassandra.java (line 679) Internal error processing get_slice java.lang.RuntimeException: java.util.concurrent.TimeoutException: Operation timed out - received only 2 responses from 172.16.129.75:7000172.16.129.72:7000 . at org.apache.cassandra.service.CassandraServer.readColumnFamily(Ca= ssandraServer.java:108) at org.apache.cassandra.service.CassandraServer.getSlice(CassandraS= erver.java:182) at org.apache.cassandra.service.CassandraServer.multigetSliceIntern= al(CassandraServer.java:251) at org.apache.cassandra.service.CassandraServer.get_slice(Cassandra= Server.java:220) at org.apache.cassandra.service.Cassandra$Processor$get_slice.proce= ss(Cassandra.java:671) at org.apache.cassandra.service.Cassandra$Processor.process(Cassand= ra.java:627) at org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TTh= readPoolServer.java:253) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoo= lExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExe= cutor.java:908) at java.lang.Thread.run(Thread.java:619) Caused by: java.util.concurrent.TimeoutException: Operation timed out - received only 2 responses from 172.16.129.75:7000172.16.129.72:7000 . at org.apache.cassandra.service.QuorumResponseHandler.get(QuorumRes= ponseHandler.java:88) at org.apache.cassandra.service.StorageProxy.strongRead(StorageProx= y.java:395) at org.apache.cassandra.service.StorageProxy.readProtocol(StoragePr= oxy.java:317) at org.apache.cassandra.service.CassandraServer.readColumnFamily(Ca= ssandraServer.java:100) ... 9 more > > On Mon, Oct 19, 2009 at 7:40 PM, Edmond Lau wrote: >> Usually I'm trying to read 500 columns (~250KB) out of the 30K columns >> (~15MB) of the supercolumn. =A0But the same issues happen when I drop >> down to 100 (~50KB) columns. =A0The columns I request from get_slice() >> are named, i.e. I'm not reading 500 consecutive columns. >> >> Edmond >> >> On Mon, Oct 19, 2009 at 5:36 PM, Jonathan Ellis wrot= e: >>> How much of the row that fails are you trying to read at once? >>> >>> On Mon, Oct 19, 2009 at 7:30 PM, Edmond Lau wrote: >>>> Whenever I try to do a quorum read on a row with a particularly large >>>> supercolumn with get_slice under high load, cassandra throws timeouts. >>>> =A0The reads for that row repeatedly fail until load decreases, but >>>> smaller reads still succeed during that time. =A0bin/nodeprobe info >>>> shows that the read latency for the column family spikes to up 6-8 >>>> seconds. =A0I've run into this issue since I started to play with >>>> cassandra, but thought that it might go away with beefier nodes. =A0I'= ve >>>> since gotten more powerful machines, but the timeouts still happen. >>>> >>>> Some details: >>>> - cassandra 0.4.1 >>>> - 5 nodes, each with 12-core 800MHz with 8GB RAM, 5GB heap size >>>> - replication factor of 3 >>>> - RandomPartitioner >>>> - row that fails has a supercolumn with ~30K subcolumns, ~500 bytes >>>> per cell, ~15MB total >>>> - my failed quorum read lists 500 columns to read in the get_slice >>>> call, but the same happens even when I read 100. >>>> >>>> The nodes either timeout with 0 or 1 responses (2 of 3 required for a >>>> quorum read): >>>> >>>> ERROR [pool-1-thread-24] 2009-10-20 00:07:43,851 Cassandra.java (line >>>> 679) Internal error processing get_slice >>>> java.lang.RuntimeException: java.util.concurrent.TimeoutException: >>>> Operation timed out - received only 0 responses from =A0. >>>> =A0 =A0 =A0 =A0at org.apache.cassandra.service.CassandraServer.readCol= umnFamily(CassandraServer.java:108) >>>> =A0 =A0 =A0 =A0at org.apache.cassandra.service.CassandraServer.getSlic= e(CassandraServer.java:182) >>>> =A0 =A0 =A0 =A0at org.apache.cassandra.service.CassandraServer.multige= tSliceInternal(CassandraServer.java:251) >>>> =A0 =A0 =A0 =A0at org.apache.cassandra.service.CassandraServer.get_sli= ce(CassandraServer.java:220) >>>> =A0 =A0 =A0 =A0at org.apache.cassandra.service.Cassandra$Processor$get= _slice.process(Cassandra.java:671) >>>> =A0 =A0 =A0 =A0at org.apache.cassandra.service.Cassandra$Processor.pro= cess(Cassandra.java:627) >>>> =A0 =A0 =A0 =A0at org.apache.thrift.server.TThreadPoolServer$WorkerPro= cess.run(TThreadPoolServer.java:253) >>>> =A0 =A0 =A0 =A0at java.util.concurrent.ThreadPoolExecutor$Worker.runTa= sk(ThreadPoolExecutor.java:886) >>>> =A0 =A0 =A0 =A0at java.util.concurrent.ThreadPoolExecutor$Worker.run(T= hreadPoolExecutor.java:908) >>>> =A0 =A0 =A0 =A0at java.lang.Thread.run(Thread.java:619) >>>> Caused by: java.util.concurrent.TimeoutException: Operation timed out >>>> - received only 0 responses from =A0. >>>> =A0 =A0 =A0 =A0at org.apache.cassandra.service.QuorumResponseHandler.g= et(QuorumResponseHandler.java:88) >>>> =A0 =A0 =A0 =A0at org.apache.cassandra.service.StorageProxy.strongRead= (StorageProxy.java:395) >>>> =A0 =A0 =A0 =A0at org.apache.cassandra.service.StorageProxy.readProtoc= ol(StorageProxy.java:317) >>>> =A0 =A0 =A0 =A0at org.apache.cassandra.service.CassandraServer.readCol= umnFamily(CassandraServer.java:100) >>>> =A0 =A0 =A0 =A0... 9 more >>>> >>>> ERROR [pool-1-thread-32] 2009-10-19 23:47:21,045 Cassandra.java (line >>>> 679) Internal error processing get_slice >>>> java.lang.RuntimeException: java.util.concurrent.TimeoutException: >>>> Operation timed out - received only 1 responses from >>>> 172.16.129.75:7000 . >>>> =A0 =A0 =A0 =A0at org.apache.cassandra.service.CassandraServer.readCol= umnFamily(CassandraServer.java:108) >>>> =A0 =A0 =A0 =A0at org.apache.cassandra.service.CassandraServer.getSlic= e(CassandraServer.java:182) >>>> =A0 =A0 =A0 =A0at org.apache.cassandra.service.CassandraServer.multige= tSliceInternal(CassandraServer.java:251) >>>> =A0 =A0 =A0 =A0at org.apache.cassandra.service.CassandraServer.get_sli= ce(CassandraServer.java:220) >>>> =A0 =A0 =A0 =A0at org.apache.cassandra.service.Cassandra$Processor$get= _slice.process(Cassandra.java:671) >>>> =A0 =A0 =A0 =A0at org.apache.cassandra.service.Cassandra$Processor.pro= cess(Cassandra.java:627) >>>> =A0 =A0 =A0 =A0at org.apache.thrift.server.TThreadPoolServer$WorkerPro= cess.run(TThreadPoolServer.java:253) >>>> =A0 =A0 =A0 =A0at java.util.concurrent.ThreadPoolExecutor$Worker.runTa= sk(ThreadPoolExecutor.java:886) >>>> =A0 =A0 =A0 =A0at java.util.concurrent.ThreadPoolExecutor$Worker.run(T= hreadPoolExecutor.java:908) >>>> =A0 =A0 =A0 =A0at java.lang.Thread.run(Thread.java:619) >>>> Caused by: java.util.concurrent.TimeoutException: Operation timed out >>>> - received only 1 responses from 172.16.129.75:7000 . >>>> =A0 =A0 =A0 =A0at org.apache.cassandra.service.QuorumResponseHandler.g= et(QuorumResponseHandler.java:88) >>>> =A0 =A0 =A0 =A0at org.apache.cassandra.service.StorageProxy.strongRead= (StorageProxy.java:395) >>>> =A0 =A0 =A0 =A0at org.apache.cassandra.service.StorageProxy.readProtoc= ol(StorageProxy.java:317) >>>> =A0 =A0 =A0 =A0at org.apache.cassandra.service.CassandraServer.readCol= umnFamily(CassandraServer.java:100) >>>> =A0 =A0 =A0 =A0... 9 more >>>> >>>> Any ideas what the issue might be? >>>> >>>> Edmond >>>> >>> >> >