Using CouchbaseClient to connect

I just wrapped the call
new CouchbaseClient(hosts, bucket, user, password);
With some System.currentTimeMillis() calls, and it takes about 10 seconds per CouchbaseClient instantiation =(

I'm just going over my local gigabit wired network, which only has a few machines on it.

Also still not sure what's consuming all of the resources.

Switched log4j to DEBUG level and got slightly more information

This is the log for a single connection instantiation:

20111109.151049.078 DEBUG DefaultListableBeanFactory (1518) - Invoking init method  'init' on bean with name 'couchbaseManager'
20111109.151049.870 INFO  MemcachedConnection (?) - Added {QA sa=/192.168.1.3:11210, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0} to connect queue
20111109.151049.873 DEBUG VBucketNodeLocator (?) - Updating nodesMap in VBucketNodeLocator.
20111109.151056.778 DEBUG VBucketNodeLocator (?) - Adding node with hostname 192.168.1.3:11210 and address 192.168.1.3:11210.
20111109.151056.778 DEBUG VBucketNodeLocator (?) - Node added is {QA sa=192.168.1.3/192.168.1.3:11210, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=8}.
20111109.151056.779 DEBUG MemcachedConnection (?) - Done dealing with queue.
20111109.151056.779 INFO  CouchbaseClient (?) - viewmode property isn't defined. Setting viewmode to production mode
20111109.151056.779 DEBUG MemcachedConnection (?) - Selecting with delay of 0ms
20111109.151056.780 DEBUG MemcachedConnection (?) - Selected 1, selected 1 keys
20111109.151056.781 DEBUG MemcachedConnection (?) - Handling IO for:  sun.nio.ch.SelectionKeyImpl@66c360a5 (r=false, w=false, c=true, op={QA sa=192.168.1.3/192.168.1.3:11210, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=8})
20111109.151056.781 INFO  MemcachedConnection (?) - Connection state changed for sun.nio.ch.SelectionKeyImpl@66c360a5
20111109.151056.785 DEBUG BinaryMemcachedNodeImpl (?) - Setting interested opts to 0
20111109.151056.786 DEBUG MemcachedConnection (?) - Handling queue
20111109.151056.786 DEBUG BinaryMemcachedNodeImpl (?) - Setting interested opts to 0
20111109.151056.786 DEBUG MemcachedConnection (?) - Done dealing with queue.
20111109.151056.786 DEBUG MemcachedConnection (?) - Selecting with delay of 0ms
20111109.151056.849 DEBUG MemcachedConnection (?) - Added SASL auth operation to {QA sa=192.168.1.3/192.168.1.3:11210, #Rops=0, #Wops=0, #iq=1, topRop=null, topWop=null, toWrite=0, interested=0}
20111109.151056.849 DEBUG MemcachedConnection (?) - No selectors ready, interrupted: false
20111109.151056.850 DEBUG MemcachedConnection (?) - Handling queue
20111109.151056.850 DEBUG BinaryMemcachedNodeImpl (?) - Setting interested opts to 4
20111109.151056.850 DEBUG MemcachedConnection (?) - Done dealing with queue.
20111109.151056.850 DEBUG MemcachedConnection (?) - Selecting with delay of 0ms
20111109.151056.851 DEBUG MemcachedConnection (?) - Selected 1, selected 1 keys
20111109.151056.851 DEBUG MemcachedConnection (?) - Handling IO for:  sun.nio.ch.SelectionKeyImpl@66c360a5 (r=false, w=true, c=false, op={QA sa=192.168.1.3/192.168.1.3:11210, #Rops=0, #Wops=1, #iq=0, topRop=null, topWop=SASL auth operation, toWrite=0, interested=4})
20111109.151056.851 DEBUG SASLAuthOperationImpl (?) - Transitioned state from WRITE_QUEUED to WRITING
20111109.151056.854 DEBUG BinaryMemcachedNodeImpl (?) - After copying stuff from SASL auth operation: java.nio.DirectByteBuffer[pos=38 lim=16384 cap=16384]
20111109.151056.854 DEBUG SASLAuthOperationImpl (?) - Transitioned state from WRITING to READING
20111109.151056.854 DEBUG BinaryMemcachedNodeImpl (?) - Finished writing SASL auth operation
20111109.151056.854 DEBUG BinaryMemcachedNodeImpl (?) - Wrote 38 bytes
20111109.151056.855 DEBUG BinaryMemcachedNodeImpl (?) - Setting interested opts to 1
20111109.151056.855 DEBUG MemcachedConnection (?) - Done dealing with queue.
20111109.151056.855 DEBUG MemcachedConnection (?) - Selecting with delay of 0ms
20111109.151056.855 DEBUG MemcachedConnection (?) - Selected 1, selected 1 keys
20111109.151056.856 DEBUG MemcachedConnection (?) - Handling IO for:  sun.nio.ch.SelectionKeyImpl@66c360a5 (r=true, w=false, c=false, op={QA sa=192.168.1.3/192.168.1.3:11210, #Rops=1, #Wops=0, #iq=0, topRop=SASL auth operation, topWop=null, toWrite=0, interested=1})
20111109.151056.856 DEBUG MemcachedConnection (?) - Read 37 bytes
20111109.151056.856 DEBUG SASLAuthOperationImpl (?) - Reading 24 header bytes
20111109.151056.856 DEBUG SASLAuthOperationImpl (?) - Reading 13 payload bytes
20111109.151056.856 INFO  AuthThread (?) - Authenticated to 192.168.1.3/192.168.1.3:11210
20111109.151056.857 DEBUG SASLAuthOperationImpl (?) - Transitioned state from READING to COMPLETE
20111109.151056.857 DEBUG MemcachedConnection (?) - Completed read op: SASL auth operation and giving the next 0 bytes
20111109.151056.857 DEBUG BinaryMemcachedNodeImpl (?) - Setting interested opts to 0
20111109.151056.857 DEBUG MemcachedConnection (?) - Done dealing with queue.
20111109.151056.857 DEBUG MemcachedConnection (?) - Selecting with delay of 0ms
20111109.151101.365 INFO  CouchbaseConnection (?) - Added 192.168.1.3/192.168.1.3:5984 to connect queue

From watching the log output, after these two calls there are huge pauses:

20111109.151049.873 DEBUG VBucketNodeLocator (?) - Updating nodesMap in VBucketNodeLocator.

and

20111109.151056.857 DEBUG MemcachedConnection (?) - Selecting with delay of 0ms

(Updated to include some output before and after the series to see the timing changes)

Still no closer to figuring out why this is so ungodly slow.

Some profiling screenshots

http://imgur.com/a/EcNhY

May have some insight, might not be the spymemcached library at all.

using curl:

curl http://IP:8091/pools/default

Works fine, BUT

curl http://IP:8091/pools/default/bucketsStreaming/BUCKET

Will almost instantly start dumping data, but the HTTP request is never terminated properly from the server. Curl will hang indefinitely, until I hit CTRL+C.

I'm assuming the 10s lag seen above is the default timeout from a HTTP request, buried in one of the libraries that spymemcached is depending on.

Nevermind, back to square 0.

curl http://IP:8091/pools/default/buckets/BUCKET

is the non-streaming API (ie it closes the http session).

I also ran wireshark to see what the spymemcached driver is actually requesting during these long pauses, and it doesn't look like it's even hitting any streaming API calls. Also, even locking on network IO wouldn't explain the 100% cpu usage.

Interesting update. I installed couchbase locally on my dev box, and there's no more 10s wait for each connection. However, still using 100% of all 4 of my poor cores.

First off, thanks for all of the detailed information!

Second, I can't immediately explain this I'm sorry to say. From the profiling it looks like all of the CPU time is in handleIO() of MemcachedConnection. That shouldn't actively use CPU time as it has a set of MemcachedNode objects, each of which have a TCP connection in a non-blocking state. It's event driven, so it shouldn't actually use CPU time if there's nothing to be read or written.

Am I reading that profile correctly? That's CPU time, not wall clock time? It's not clear from the screenshots. It'd be normal for there to be that much wall clock time.

Also, can you verify that the JVM is using 100% of the CPU?

The 10s wait is also really hard to explain.

Which Java VM and OS version are you using?

Just wanted an clear up a few of the questions you have right now and tomorrow I will try to find some time to look into some of your other issues. Looks like the two issues so far are:

1. Spymemcached takes too long to connect to Couchbase
2. Spymemcached consumes too much cpu (Just to be clear are you running any load or is Spy sitting idle?)

First off, in my testing I haven't seen either of these issues, but I test mostly on OSX and Linux as opposed to Windows. Either way we definitely want to figure out what's going on here. Also, I'm glad to hear that issue 1 seems to go away when Couchbase and Spymemcached are on the same machine.

Below are some quick answers to some of the other things you asked. Let me know if I missed anything

>> Using the example from the tutorial, there's only one example of a connection, and it gives no information on how the bucket is actually configured (ie as SASL protected or dedicated port).

When you use the constructors in CouchbaseClient there are parameters for bucket name and password. If your using a non-sasl bucket then the password is "". If your using a sasl bucket then that bucket will have a password. Spymecached will take care of all of the sasl connection stuff for you if it is needed. It will also get the ret of the stuff it needs, like other ports to use, from Couchbase.

>> So connecting to port 8091 seems to be mandatory (is this the only way to connect to the REST API?).

Yes, this is where Spymemcached gets all of it's configuration stuff. This is not the place to do CouchAPI request. If you want to do things like add bucket or other cluster management stuff then you use this port, but Spymemcached doesn't support those kinds of things. Couchbase ships with some shell scripts to di this kind of stuff, but if you want a java API you can find one here: https://github.com/mikewied/java-membase-rest-client. I haven't worked on it or used it in a while so it might be out of date, but if you file issues for it on my github page I will get around to fixing them.

Let me know if you have any other questions.

Np, I know how difficult it is to find bugs in large software products =)

The profile is in seconds. I'm not sure how it's being measured, I haven't had to use the eclipse profiler very often.

When I start up the tomcat servlet, "javaw.exe" consumes 90+ percent of my CPU. Essentially anything that's not going to another process.

The 10s wait time disappeared when I switched to running a local install of couchbase on my dev box. That may have had something to do with the ATOM cpu on my small linux test box. Actually about to test on some EC2 nodes to see if the problem exists there as well.

Windows 7 on my dev box, which is running both Couchbase and Eclipse/tomcat.
Eclipse Helios
JDK version 1.6.0_21
Tomcat version 6.0.29

I think I missed a question earlier, 100% of the CPU is being consumed when the app and connection should be idle. IE there are no requests/responses taking place.

Ok, also consuming all of the CPU on an EC2 instance running CentOS 5.4 with Java 1.6.0_14.

Going back into the wrapper I made for Spring to instantiate the connections and make sure I didn't do anything stupid. I started with the one I've been using for years to connect to Memcached with SpyMemcached, but who knows.

Just wrote some quick unit tests that connect, insert, get, delete, disconnect.
I inserted Thread.sleep's between each set of actions to simulate it running in a server-like environment. Even while the thread is sleeping, the CPU seems to thrash, although not as bad as observed earlier. It also seems the more connections are open the more thrashing is observed. I started with 1 connection and had 1 CPU core at 100%, and then upped it to 5 connections and saw all 4 cores go to 95%. All essentially observed during the last sleep command, which is 10 seconds.

test case uploaded to bug report here:
http://www.couchbase.org/issues/browse/SPY-64

Semi-interesting side note: I'm using the ektorp CouchDB driver to communicate directly with the CouchDB API on my couchbase servers. Reads and deletes, are very quick, but inserts take up to 1 second. Switching back to the couchbase driver, inserts are extremely fast (although still having the 100% cpu issue).

Could you show your examples how to use log4j to control couchbase connection log info?

thanks

20111109.151049.078 DEBUG DefaultListableBeanFactory (1518) - Invoking init method  'init' on bean with name 'couchbaseManager'
20111109.151049.870 INFO  MemcachedConnection (?) - Added {QA sa=/192.168.1.3:11210, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0} to connect queue
20111109.151049.873 DEBUG VBucketNodeLocator (?) - Updating nodesMap in VBucketNodeLocator.
20111109.151056.778 DEBUG VBucketNodeLocator (?) - Adding node with hostname 192.168.1.3:11210 and address 192.168.1.3:11210.
20111109.151056.778 DEBUG VBucketNodeLocator (?) - Node added is {QA sa=192.168.1.3/192.168.1.3:11210, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=8}.
20111109.151056.779 DEBUG MemcachedConnection (?) - Done dealing with queue.
20111109.151056.779 INFO  CouchbaseClient (?) - viewmode property isn't defined. Setting viewmode to production mode
20111109.151056.779 DEBUG MemcachedConnection (?) - Selecting with delay of 0ms
20111109.151056.780 DEBUG MemcachedConnection (?) - Selected 1, selected 1 keys
20111109.151056.781 DEBUG MemcachedConnection (?) - Handling IO for:  sun.nio.ch.SelectionKeyImpl@66c360a5 (r=false, w=false, c=true, op={QA sa=192.168.1.3/192.168.1.3:11210, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=8})
20111109.151056.781 INFO  MemcachedConnection (?) - Connection state changed for sun.nio.ch.SelectionKeyImpl@66c360a5
20111109.151056.785 DEBUG BinaryMemcachedNodeImpl (?) - Setting interested opts to 0
20111109.151056.786 DEBUG MemcachedConnection (?) - Handling queue
20111109.151056.786 DEBUG BinaryMemcachedNodeImpl (?) - Setting interested opts to 0
20111109.151056.786 DEBUG MemcachedConnection (?) - Done dealing with queue.
20111109.151056.786 DEBUG MemcachedConnection (?) - Selecting with delay of 0ms
20111109.151056.849 DEBUG MemcachedConnection (?) - Added SASL auth operation to {QA sa=192.168.1.3/192.168.1.3:11210, #Rops=0, #Wops=0, #iq=1, topRop=null, topWop=null, toWrite=0, interested=0}
20111109.151056.849 DEBUG MemcachedConnection (?) - No selectors ready, interrupted: false
20111109.151056.850 DEBUG MemcachedConnection (?) - Handling queue
20111109.151056.850 DEBUG BinaryMemcachedNodeImpl (?) - Setting interested opts to 4
20111109.151056.850 DEBUG MemcachedConnection (?) - Done dealing with queue.
20111109.151056.850 DEBUG MemcachedConnection (?) - Selecting with delay of 0ms
20111109.151056.851 DEBUG MemcachedConnection (?) - Selected 1, selected 1 keys
20111109.151056.851 DEBUG MemcachedConnection (?) - Handling IO for:  sun.nio.ch.SelectionKeyImpl@66c360a5 (r=false, w=true, c=false, op={QA sa=192.168.1.3/192.168.1.3:11210, #Rops=0, #Wops=1, #iq=0, topRop=null, topWop=SASL auth operation, toWrite=0, interested=4})
20111109.151056.851 DEBUG SASLAuthOperationImpl (?) - Transitioned state from WRITE_QUEUED to WRITING
20111109.151056.854 DEBUG BinaryMemcachedNodeImpl (?) - After copying stuff from SASL auth operation: java.nio.DirectByteBuffer[pos=38 lim=16384 cap=16384]
20111109.151056.854 DEBUG SASLAuthOperationImpl (?) - Transitioned state from WRITING to READING
20111109.151056.854 DEBUG BinaryMemcachedNodeImpl (?) - Finished writing SASL auth operation
20111109.151056.854 DEBUG BinaryMemcachedNodeImpl (?) - Wrote 38 bytes
20111109.151056.855 DEBUG BinaryMemcachedNodeImpl (?) - Setting interested opts to 1
20111109.151056.855 DEBUG MemcachedConnection (?) - Done dealing with queue.
20111109.151056.855 DEBUG MemcachedConnection (?) - Selecting with delay of 0ms
20111109.151056.855 DEBUG MemcachedConnection (?) - Selected 1, selected 1 keys
20111109.151056.856 DEBUG MemcachedConnection (?) - Handling IO for:  sun.nio.ch.SelectionKeyImpl@66c360a5 (r=true, w=false, c=false, op={QA sa=192.168.1.3/192.168.1.3:11210, #Rops=1, #Wops=0, #iq=0, topRop=SASL auth operation, topWop=null, toWrite=0, interested=1})
20111109.151056.856 DEBUG MemcachedConnection (?) - Read 37 bytes
20111109.151056.856 DEBUG SASLAuthOperationImpl (?) - Reading 24 header bytes
20111109.151056.856 DEBUG SASLAuthOperationImpl (?) - Reading 13 payload bytes
20111109.151056.856 INFO  AuthThread (?) - Authenticated to 192.168.1.3/192.168.1.3:11210
20111109.151056.857 DEBUG SASLAuthOperationImpl (?) - Transitioned state from READING to COMPLETE
20111109.151056.857 DEBUG MemcachedConnection (?) - Completed read op: SASL auth operation and giving the next 0 bytes
20111109.151056.857 DEBUG BinaryMemcachedNodeImpl (?) - Setting interested opts to 0
20111109.151056.857 DEBUG MemcachedConnection (?) - Done dealing with queue.
20111109.151056.857 DEBUG MemcachedConnection (?) - Selecting with delay of 0ms
20111109.151101.365 INFO  CouchbaseConnection (?) - Added 192.168.1.3/192.168.1.3:5984 to connect queue