sun.nio.ch.SelectionKeyImpl@9d532ae has 4, interested in 5, Discarding partially completed op

[GoogleCodeExporter]

What version of the product are you using? On what operating system?
OS: RH Linux 2.6.18-128.1.10.el5 on AMD
Setup: JDK 1.6 
Tomcat: 6
Memcache: 
Spymemcache: spy-2.4.jar , memcached-2.1.jar 

Usecase: 
jasig.org's CAS with memcache as ticket registry

Tell me more...
Our application servers authentication needs for our campus. The usecase 
creates lots of SignOn tickets that are stored in Memcache. Randomly we see 
the following errors and our application throws Connection Timed Out errors 
on gets. The applicationr recovers itself over time.

2009-08-04 15:34:56.937 INFO net.spy.memcached.MemcachedConnection:  
sun.nio.ch.SelectionKeyImpl@9d532ae has 4, interested in 5
2009-08-04 15:34:56.938 INFO net.spy.memcached.MemcachedConnection:  
sun.nio.ch.SelectionKeyImpl@9d532ae has a ready op, handling IO
2009-08-04 15:34:56.938 INFO net.spy.memcached.MemcachedConnection:  
sun.nio.ch.SelectionKeyImpl@9d532ae has 4, interested in 5
2009-08-04 15:34:56.938 INFO net.spy.memcached.MemcachedConnection:  
sun.nio.ch.SelectionKeyImpl@9d532ae has a ready op, handling IO
2009-08-04 15:34:57.183 INFO net.spy.memcached.MemcachedConnection:  
Reconnecting due to exception on {QA 
sa=memcache.calnet.1918.berkeley.edu/10.254.9.42:11211, #Rops=343, 
#Wops=11174, #iq=0, 
topRop=net.spy.memcached.protocol.ascii.StoreOperationImpl@74518f5a, 
topWop=net.spy.memcached.protocol.ascii.GetOperationImpl@169a995f, 
toWrite=13, interested=5}
2009-08-04 15:34:57.191 WARN net.spy.memcached.MemcachedConnection:  
Closing, and reopening {QA xxxxx:11211, #Rops=343, #Wops=11174, #iq=0, 
topRop=net.spy.memcached.protocol.ascii.StoreOperationImpl@74518f5a, 
topWop=net.spy.memcached.protocol.ascii.GetOperationImpl@169a995f, 
toWrite=13, interested=5}, attempt 0.
2009-08-04 15:34:57.278 WARN 
net.spy.memcached.protocol.ascii.AsciiMemcachedNodeImpl:  Discarding 
partially completed op: 
net.spy.memcached.protocol.ascii.StoreOperationImpl@74518f5a
2009-08-04 15:34:57.280 WARN 
net.spy.memcached.protocol.ascii.AsciiMemcachedNodeImpl:  Discarding 
partially completed op: 

Original issue reported on code.google.com by venu.a...@gmail.com on 4 Aug 2009 at 10:59

[GoogleCodeExporter]

Are you running with assertions enabled?  If not, can you?  It's got a bit of a
safety net in there, but this looks like it's getting into a condition it 
shouldn't
be able to get into.

Original comment by dsalli...@gmail.com on 5 Aug 2009 at 7:15

[GoogleCodeExporter]

Are you still having this issue in later releases?  Can you provide a bit more 
info?

Original comment by dsalli...@gmail.com on 11 Nov 2009 at 7:39

• Changed state: NeedInfo

[GoogleCodeExporter]

So, were are here again. Today, the problem manifested again in production. It 
sustained for 10minutes. Here is the log output....this went on for 10min+ and 
recovered itself. No we have not enabled assertions. What I am curious is, what 
could 
be the root cause of this issue? I am using...memcached-2.3.1.jar, upgraded 
from 
memcached-2.1.jar.

Log out that goes on for 11+minutes.

catalina.out:2010-02-22 11:48:39.153 INFO 
net.spy.memcached.MemcachedConnection:  
sun.nio.ch.SelectionKeyImpl@24a5c9e4 has 4, interested in 1
catalina.out:2010-02-22 11:48:39.153 INFO 
net.spy.memcached.MemcachedConnection:  
sun.nio.ch.SelectionKeyImpl@24a5c9e4 has a ready op, handling IO

Original comment by venu.a...@gmail.com on 23 Feb 2010 at 1:39

[GoogleCodeExporter]

catalina.out:2010-02-22 11:59:45.173 INFO 
net.spy.memcached.MemcachedConnection:  
sun.nio.ch.SelectionKeyImpl@24a5c9e4 has 4, interested in 5
catalina.out:2010-02-22 11:59:45.212 INFO 
net.spy.memcached.MemcachedConnection:  
sun.nio.ch.SelectionKeyImpl@24a5c9e4 has 4, interested in 5
catalina.out:2010-02-22 11:59:45.308 INFO 
net.spy.memcached.MemcachedConnection:  
sun.nio.ch.SelectionKeyImpl@24a5c9e4 has 4, interested in 5

Original comment by venu.a...@gmail.com on 23 Feb 2010 at 1:50

[GoogleCodeExporter]

2.4.2 has a fix that may very well take care of this.  Specifically 
32762f8b7908d91de10fb74d905398818b1552e7

Original comment by dsalli...@gmail.com on 23 Feb 2010 at 2:15

[GoogleCodeExporter]

thank you, I reviewed the thread=68,  I will deploy and test it out.

Original comment by venu.a...@gmail.com on 23 Feb 2010 at 2:46

[GoogleCodeExporter]

hi, we deployed 2.4.2 and the problem did not go away. Just a fyi. Any clue 
what 
might be causing this issue. The server times out on all memcache get requests 
at 
this point.

2010-02-28 16:55:32.009 INFO net.spy.memcached.MemcachedConnection:  
sun.nio.ch.SelectionKeyImpl@290e1513 has 4, interes in 5
2010-02-28 16:55:32.010 INFO net.spy.memcached.MemcachedConnection:  
sun.nio.ch.SelectionKeyImpl@290e1513 has 4, interes in 5

Original comment by venu.a...@gmail.com on 2 Mar 2010 at 4:57

[GoogleCodeExporter]

This happends when you overwhelm the queue with too many OUTSTANDING requests. 
The solution is to limit the number of outstanding requests to a manageable 
size. A simple solution is to use a linked list to maintain a buffer.

LinkedList<Future<Boolean>> operationBuffer = new 
LinkedList<Future<Boolean>>(100);

for(int i = 0 ; i < 1000000; i++)
{
    operationBuffer.add(client.set(key, ttl, value)); 

    if(operationBuffer.size >= 100)
    {
        operationBuffer.removeFirst().get(1, TimeUnit.SECONDS);
    }
}

This technique will throttle you the to maximum write speed of the cache and 
give memcached a buffer of 100 outstanding requests.

Original comment by brianama...@gmail.com on 24 Feb 2012 at 2:25

[GoogleCodeExporter]

BTW, this works for any outstanding requests... not just set

Original comment by brianama...@gmail.com on 24 Feb 2012 at 2:26