You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@cassandra.apache.org by Andy Skalet <ae...@bitjug.com> on 2011/02/17 08:01:56 UTC
frequent client exceptions on 0.7.0
Hello,
We were occasionally experiencing client exceptions with 0.6.3, so we
upgraded to 0.7.0 a couple weeks ago, but unfortunately we now get
more client exceptions, and more frequently. Also, occasionally
nodetool ring will show a node Down even though cassandra is still
running and the node will be up again shortly. We run nodetool ring
every half hour or so for monitoring, otherwise we probably would not
have noticed.
I'm trying to determine whether we are hitting some bugs, just don't
have enough hardware for our application, or have made some error in
configuration. I would happy to provide any more information or run
tests to narrow down the problem. Below are some exceptions we see
several distinct times every day:
1)
File "/usr/local/lib/python2.6/dist-packages/pycassa-1.0.4-py2.6.egg/pycassa/columnfamily.py",
line 430, in get
self._rcl(read_consistency_level))
File "/usr/local/lib/python2.6/dist-packages/pycassa-1.0.4-py2.6.egg/pycassa/pool.py",
line 397, in new_f
result = getattr(super(ConnectionWrapper, self), f.__name__)(*args, **kwargs)
File "/usr/local/lib/python2.6/dist-packages/pycassa-1.0.4-py2.6.egg/pycassa/cassandra/Cassandra.py",
line 432, in get_slice
return self.recv_get_slice()
File "/usr/local/lib/python2.6/dist-packages/pycassa-1.0.4-py2.6.egg/pycassa/cassandra/Cassandra.py",
line 446, in recv_get_slice
(fname, mtype, rseqid) = self._iprot.readMessageBegin()
File "/usr/local/lib/python2.6/dist-packages/Thrift-0.5.0-py2.6-linux-i686.egg/thrift/protocol/TBinaryProtocol.py",
line 126, in readMessageBegin
sz = self.readI32()
File "/usr/local/lib/python2.6/dist-packages/Thrift-0.5.0-py2.6-linux-i686.egg/thrift/protocol/TBinaryProtocol.py",
line 203, in readI32
buff = self.trans.readAll(4)
File "/usr/local/lib/python2.6/dist-packages/Thrift-0.5.0-py2.6-linux-i686.egg/thrift/transport/TTransport.py",
line 63, in readAll
raise EOFError()
EOFError
2)
File "/usr/local/lib/python2.6/dist-packages/pycassa-1.0.4-py2.6.egg/pycassa/columnfamily.py",
line 710, in insert
res = self._tlocal.client.insert(key, cp, column,
self._wcl(write_consistency_level))
File "/usr/local/lib/python2.6/dist-packages/pycassa-1.0.4-py2.6.egg/pycassa/pool.py",
line 421, in new_f
return new_f(self, *args, **kwargs)
File "/usr/local/lib/python2.6/dist-packages/pycassa-1.0.4-py2.6.egg/pycassa/pool.py",
line 421, in new_f
return new_f(self, *args, **kwargs)
File "/usr/local/lib/python2.6/dist-packages/pycassa-1.0.4-py2.6.egg/pycassa/pool.py",
line 421, in new_f
return new_f(self, *args, **kwargs)
File "/usr/local/lib/python2.6/dist-packages/pycassa-1.0.4-py2.6.egg/pycassa/pool.py",
line 406, in new_f
raise MaximumRetryException('Retried %d times' % self._retry_count)
MaximumRetryException: Retried 4 times
3)
return ColumnFamily(client, bucket_name)
File "/usr/local/lib/python2.6/dist-packages/pycassa-1.0.4-py2.6.egg/pycassa/columnfamily.py",
line 122, in __init__
self._obtain_connection()
File "/usr/local/lib/python2.6/dist-packages/pycassa-1.0.4-py2.6.egg/pycassa/columnfamily.py",
line 359, in _obtain_connection
self._tlocal.client = self.pool.get()
File "/usr/local/lib/python2.6/dist-packages/pycassa-1.0.4-py2.6.egg/pycassa/pool.py",
line 724, in get
conn = self._create_connection()
File "/usr/local/lib/python2.6/dist-packages/pycassa-1.0.4-py2.6.egg/pycassa/pool.py",
line 122, in _create_connection
wrapper = self._get_new_wrapper(server)
File "/usr/local/lib/python2.6/dist-packages/pycassa-1.0.4-py2.6.egg/pycassa/pool.py",
line 640, in _get_new_wrapper
credentials=self.credentials)
File "/usr/local/lib/python2.6/dist-packages/pycassa-1.0.4-py2.6.egg/pycassa/pool.py",
line 317, in __init__
super(ConnectionWrapper, self).__init__(*args, **kwargs)
File "/usr/local/lib/python2.6/dist-packages/pycassa-1.0.4-py2.6.egg/pycassa/connection.py",
line 38, in __init__
server_api_version = int(self.describe_version().split('.', 1)[0])
File "/usr/local/lib/python2.6/dist-packages/pycassa-1.0.4-py2.6.egg/pycassa/cassandra/Cassandra.py",
line 947, in describe_version
return self.recv_describe_version()
File "/usr/local/lib/python2.6/dist-packages/pycassa-1.0.4-py2.6.egg/pycassa/cassandra/Cassandra.py",
line 957, in recv_describe_version
(fname, mtype, rseqid) = self._iprot.readMessageBegin()
File "/usr/local/lib/python2.6/dist-packages/Thrift-0.5.0-py2.6-linux-i686.egg/thrift/protocol/TBinaryProtocol.py",
line 126, in readMessageBegin
sz = self.readI32()
File "/usr/local/lib/python2.6/dist-packages/Thrift-0.5.0-py2.6-linux-i686.egg/thrift/protocol/TBinaryProtocol.py",
line 203, in readI32
buff = self.trans.readAll(4)
File "/usr/local/lib/python2.6/dist-packages/Thrift-0.5.0-py2.6-linux-i686.egg/thrift/transport/TTransport.py",
line 58, in readAll
chunk = self.read(sz-have)
File "/usr/local/lib/python2.6/dist-packages/Thrift-0.5.0-py2.6-linux-i686.egg/thrift/transport/TTransport.py",
line 272, in read
self.readFrame()
File "/usr/local/lib/python2.6/dist-packages/Thrift-0.5.0-py2.6-linux-i686.egg/thrift/transport/TTransport.py",
line 276, in readFrame
buff = self.__trans.readAll(4)
File "/usr/local/lib/python2.6/dist-packages/Thrift-0.5.0-py2.6-linux-i686.egg/thrift/transport/TTransport.py",
line 58, in readAll
chunk = self.read(sz-have)
File "/usr/local/lib/python2.6/dist-packages/Thrift-0.5.0-py2.6-linux-i686.egg/thrift/transport/TSocket.py",
line 94, in read
buff = self.handle.recv(sz)
error: [Errno 104] Connection reset by peer
Thanks in advance for any insight,
Andy
Re: frequent client exceptions on 0.7.0
Posted by Peter Schuller <pe...@infidyne.com>.
> AFAIK the MemtablePostFlusher is the TP writing sstables, if it has a queue then there is the potential for writes to block while it waits for Memtables to be flushed. Take a look at your Memtable settings per CF, could it be that all the Memtables are flushing at once? There is info in the logs about when this happens.
I didn't follow this thread closely, but based on the above maybe have
a look at:
https://issues.apache.org/jira/browse/CASSANDRA-1955
https://issues.apache.org/jira/browse/CASSANDRA-1991
(And no, I haven't had the time to do anything more on those since
what's there. Sorry.)
--
/ Peter Schuller
Re: frequent client exceptions on 0.7.0
Posted by Aaron Morton <aa...@thelastpickle.com>.
AFAIK the MemtablePostFlusher is the TP writing sstables, if it has a queue then there is the potential for writes to block while it waits for Memtables to be flushed. Take a look at your Memtable settings per CF, could it be that all the Memtables are flushing at once? There is info in the logs about when this happens.
One approach is to set the timeout high, so they are more likely to flush due to ops or throughput.
Aaron
On 19/02/2011, at 10:09 AM, Andy Skalet <ae...@bitjug.com> wrote:
> On Thu, Feb 17, 2011 at 12:22 PM, Aaron Morton <aa...@thelastpickle.com> wrote:
>> Messages been dropped means the machine node is overloaded. Look at the thread pool stats to see which thread pools have queues. It may be IO related, so also check the read and write latency on the CF and use iostat.
>>
>> i would try those first, then jump into GC land.
>
> Thanks, Aaron. I am looking at the thread pool queues; not enough
> data on that yet but so far I've seen queues in the ReadStage from
> 4-30 (once 100) and MemtablePostFlusher as much as 70, though not consistently.
>
> The read latencies on the CFs on this cluster are sitting around
> 20-40ms, and the write latencies are are all around .01ms. That seems
> good to me, but I don't have a baseline.
>
> I do see high (90-100%) utilization from time to time on the disk that
> holds the data, based on reads. This doesn't surprise me too much
> because IO on these machines is fairly limited in performance.
>
> Does this sound like the node is overloaded?
>
> Andy
Re: frequent client exceptions on 0.7.0
Posted by Andy Skalet <ae...@bitjug.com>.
On Thu, Feb 17, 2011 at 12:22 PM, Aaron Morton <aa...@thelastpickle.com> wrote:
> Messages been dropped means the machine node is overloaded. Look at the thread pool stats to see which thread pools have queues. It may be IO related, so also check the read and write latency on the CF and use iostat.
>
> i would try those first, then jump into GC land.
Thanks, Aaron. I am looking at the thread pool queues; not enough
data on that yet but so far I've seen queues in the ReadStage from
4-30 (once 100) and MemtablePostFlusher as much as 70, though not consistently.
The read latencies on the CFs on this cluster are sitting around
20-40ms, and the write latencies are are all around .01ms. That seems
good to me, but I don't have a baseline.
I do see high (90-100%) utilization from time to time on the disk that
holds the data, based on reads. This doesn't surprise me too much
because IO on these machines is fairly limited in performance.
Does this sound like the node is overloaded?
Andy
Re: frequent client exceptions on 0.7.0
Posted by Aaron Morton <aa...@thelastpickle.com>.
Messages been dropped means the machine node is overloaded. Look at the thread pool stats to see which thread pools have queues. It may be IO related, so also check the read and write latency on the CF and use iostat.
i would try those first, then jump into GC land.
Aaron
On 18/02/2011, at 4:43 AM, Dan Hendry <da...@gmail.com> wrote:
> Try turning on GC logging in Cassandra-env.sh, specifically:
>
> -XX:+PrintGCApplicationStoppedTime
> -Xloggc:/var/log/cassandra/gc.log
>
> Look for things like: "Total time for which application threads were
> stopped: 52.8795600 seconds". Anything over about a few seconds may be
> causing your problem.
>
> Stop the world GC is a real pain. In my cluster I was, and still am to some
> extent, seeing each node go 'down' about 10-30 times a day and up to a few
> hundred when running major compactions (by greping through the Cassandra
> system log). GC tuning is an art into itself but if this is your problem,
> try:
> - lower memtable flush thresholds
> - reduce new gen size (which is explicitly set in 0.7.1+, the -Xmn
> setting)
> - reducing CMSInitiatingOccupancyFraction from 75 to 60 or so (maybe
> less)
> - set -XX:ParallelGCThreads=<NUMBER OF CPU CORES>
> - set -XX:ParallelCMSThreads=<NUMBER OF CPU CORES>
>
> Again, I would recommend you do some more research into GC tuning
> (http://www.oracle.com/technetwork/java/javase/gc-tuning-6-140523.html is a
> good place to start). Most of my recommendations above will probably reduce
> the chance of your nodes going 'down' but may have pretty severe negative
> performance impacts. In my cluster, I found the measures needed to ensure
> the node never (or rarely, it cant be completely prevented) went down just
> were not worth it. I have ended up running the nodes closer to the wire and
> living with an increased rate of client side exceptions and nodes going down
> for short periods.
>
> Dan
>
> -----Original Message-----
> From: Andy Skalet [mailto:aeskalet@bitjug.com]
> Sent: February-17-11 4:18
> To: Peter Schuller
> Cc: user@cassandra.apache.org
> Subject: Re: frequent client exceptions on 0.7.0
>
> On Thu, Feb 17, 2011 at 12:37 AM, Peter Schuller
> <pe...@infidyne.com> wrote:
>> Bottom line: Check /var/log/cassandra/system.log to begin with and see
>> if it's reporting anything or being restarted.
>
> Thanks, Peter.
>
> In the system.log, I see quite a few of these across several machines.
> Everything else in the log is INFO level.
>
> WARN [ScheduledTasks:1] 2011-02-17 07:19:47,491 MessagingService.java
> (line 545) Dropped 182 READ messages in the last 5000ms
> WARN [ScheduledTasks:1] 2011-02-17 08:10:06,142 MessagingService.java
> (line 545) Dropped 31 READ messages in the last 5000ms
> WARN [ScheduledTasks:1] 2011-02-17 08:11:12,237 MessagingService.java
> (line 545) Dropped 54 READ messages in the last 5000ms
> WARN [ScheduledTasks:1] 2011-02-17 08:11:17,392 MessagingService.java
> (line 545) Dropped 487 READ messages in the last 5000ms
>
> The machines are in EC2 with firewall permission to talk to each
> other, so while not the most solid of network environments, at least
> pretty common these days. System is not going down, and cassandra
> process is not dying.
>
> Andy
> No virus found in this incoming message.
> Checked by AVG - www.avg.com
> Version: 9.0.872 / Virus Database: 271.1.1/3447 - Release Date: 02/16/11
> 02:34:00
>
RE: frequent client exceptions on 0.7.0
Posted by Dan Hendry <da...@gmail.com>.
Try turning on GC logging in Cassandra-env.sh, specifically:
-XX:+PrintGCApplicationStoppedTime
-Xloggc:/var/log/cassandra/gc.log
Look for things like: "Total time for which application threads were
stopped: 52.8795600 seconds". Anything over about a few seconds may be
causing your problem.
Stop the world GC is a real pain. In my cluster I was, and still am to some
extent, seeing each node go 'down' about 10-30 times a day and up to a few
hundred when running major compactions (by greping through the Cassandra
system log). GC tuning is an art into itself but if this is your problem,
try:
- lower memtable flush thresholds
- reduce new gen size (which is explicitly set in 0.7.1+, the -Xmn
setting)
- reducing CMSInitiatingOccupancyFraction from 75 to 60 or so (maybe
less)
- set -XX:ParallelGCThreads=<NUMBER OF CPU CORES>
- set -XX:ParallelCMSThreads=<NUMBER OF CPU CORES>
Again, I would recommend you do some more research into GC tuning
(http://www.oracle.com/technetwork/java/javase/gc-tuning-6-140523.html is a
good place to start). Most of my recommendations above will probably reduce
the chance of your nodes going 'down' but may have pretty severe negative
performance impacts. In my cluster, I found the measures needed to ensure
the node never (or rarely, it cant be completely prevented) went down just
were not worth it. I have ended up running the nodes closer to the wire and
living with an increased rate of client side exceptions and nodes going down
for short periods.
Dan
-----Original Message-----
From: Andy Skalet [mailto:aeskalet@bitjug.com]
Sent: February-17-11 4:18
To: Peter Schuller
Cc: user@cassandra.apache.org
Subject: Re: frequent client exceptions on 0.7.0
On Thu, Feb 17, 2011 at 12:37 AM, Peter Schuller
<pe...@infidyne.com> wrote:
> Bottom line: Check /var/log/cassandra/system.log to begin with and see
> if it's reporting anything or being restarted.
Thanks, Peter.
In the system.log, I see quite a few of these across several machines.
Everything else in the log is INFO level.
WARN [ScheduledTasks:1] 2011-02-17 07:19:47,491 MessagingService.java
(line 545) Dropped 182 READ messages in the last 5000ms
WARN [ScheduledTasks:1] 2011-02-17 08:10:06,142 MessagingService.java
(line 545) Dropped 31 READ messages in the last 5000ms
WARN [ScheduledTasks:1] 2011-02-17 08:11:12,237 MessagingService.java
(line 545) Dropped 54 READ messages in the last 5000ms
WARN [ScheduledTasks:1] 2011-02-17 08:11:17,392 MessagingService.java
(line 545) Dropped 487 READ messages in the last 5000ms
The machines are in EC2 with firewall permission to talk to each
other, so while not the most solid of network environments, at least
pretty common these days. System is not going down, and cassandra
process is not dying.
Andy
No virus found in this incoming message.
Checked by AVG - www.avg.com
Version: 9.0.872 / Virus Database: 271.1.1/3447 - Release Date: 02/16/11
02:34:00
Re: frequent client exceptions on 0.7.0
Posted by Andy Skalet <ae...@bitjug.com>.
On Thu, Feb 17, 2011 at 12:37 AM, Peter Schuller
<pe...@infidyne.com> wrote:
> Bottom line: Check /var/log/cassandra/system.log to begin with and see
> if it's reporting anything or being restarted.
Thanks, Peter.
In the system.log, I see quite a few of these across several machines.
Everything else in the log is INFO level.
WARN [ScheduledTasks:1] 2011-02-17 07:19:47,491 MessagingService.java
(line 545) Dropped 182 READ messages in the last 5000ms
WARN [ScheduledTasks:1] 2011-02-17 08:10:06,142 MessagingService.java
(line 545) Dropped 31 READ messages in the last 5000ms
WARN [ScheduledTasks:1] 2011-02-17 08:11:12,237 MessagingService.java
(line 545) Dropped 54 READ messages in the last 5000ms
WARN [ScheduledTasks:1] 2011-02-17 08:11:17,392 MessagingService.java
(line 545) Dropped 487 READ messages in the last 5000ms
The machines are in EC2 with firewall permission to talk to each
other, so while not the most solid of network environments, at least
pretty common these days. System is not going down, and cassandra
process is not dying.
Andy
Re: frequent client exceptions on 0.7.0
Posted by Peter Schuller <pe...@infidyne.com>.
> raise EOFError()
> EOFError
[snip]
> error: [Errno 104] Connection reset by peer
Sounds like you either have a firewalling/networking issues that is
tearing down TCP connections, or your cassandra node is dying. Have
you checked the Cassandra system log? A frequent mistake is
configuring memtables thresholds far too aggressively for your heap
size, resulting in an out-of-memory error which, given Cassandra's
default JVM options, results in the node dying.
Bottom line: Check /var/log/cassandra/system.log to begin with and see
if it's reporting anything or being restarted.
--
/ Peter Schuller