TimeoutException on bucket.query

Hi all
We are using CB 3.0.1 with Java SDK 2.0.1.
While trying to query a view using bucket.query(ViewQuery) some times we get timeout exception even when there is no new documents on the DB. the DB is on a steady state no parallel insert.
The Viewquery.keys contains an array of few dozenth of keys.
The view contains a map function without reduce which take some parameters from the document and store it.

Hi @nirko,

thanks very much for posting here. It is very hard to say why this is happening without having code to reproduce or at least some logs. Can you share one or both of these? Also, 2.0.2 has been released so you probably want to use this version anyways.

Thanks!
Michael

Hello Daschl!

I seen same problem. The steps:

  1. opening a bucket:

    cluster = CouchbaseCluster.create( ip );
    bucket = cluster.openBucket(“bucket”);

  2. waiting some minutes.

  3. make a query:

    bucket.query(Query.simple(“SELECT * FROM bucket where any=‘value’”));

  4. got exception:

    java.lang.RuntimeException: java.util.concurrent.TimeoutException
    at com.couchbase.client.java.util.Blocking.blockForSingle(Blocking.java:93)
    at com.couchbase.client.java.CouchbaseBucket.query(CouchbaseBucket.java:547)
    at com.couchbase.client.java.CouchbaseBucket.query(CouchbaseBucket.java:490)

_time="2015-03-10T08:59:06+01:00" _level="INFO" _msg="Number of indexes 1" 
_time="2015-03-10T08:59:06+01:00" _level="INFO" _msg="Request View: http://IP:8092/bucket/_design/ddl_%23primary/_view/%23primary?limit=1001" 
_time="2015-03-10T08:59:06+01:00" _level="INFO" _msg="Number of entries fetched from the index 80" 
  1. the previous url:
    http://IP:8092/bucket/design/ddl%23primary/_view/%23primary?limit=1001"
    response fastly.

The cbq-dp4 query works as well.

The versions:

3.0.1-1444-rel
cbq-dp4
rxjava-1.0.8.jar
core-io-1.1.1.jar
java-client-2.1.1.jar
couchbase-client-1.4.8.jar

The bucket contains around 80 keys without any activity.

Thank you very much!
Cheers,
Huhh

hi @huhh
Since you are using N1QL DP4, you need to explicitely activate the feature in the couchbase client.
Please build your cluster object like so:

CouchbaseEnvironment env = DefaultCouchbaseEnvironment.builder()
    .queryEnabled(true) //that's the important part
    .build();
CouchbaseCluster cluster = CouchbaseCluster.create(env, "your.server.ip.here");

The logs before the timeout should show a WARN message like

WARN  CouchbaseCore:182 - Exception while Handling Request Events RequestEvent{request=null}, com.couchbase.client.core.ServiceNotAvailableException: The Query service is not enabled or no node in the cluster supports it.`

Simon

note: the fact that it logs the ServiceNotAvailableException then times out is a bug, in the next version (2.1.2) it will directly throw the exception if the query feature is not enabled.

Hello Simon!

Thank you your answer.

I forgot to write, i enabled the query mode with System.setProperty.

I debugged out the problem, and i can give this code:

import com.couchbase.client.java.*;
import com.couchbase.client.java.*;
import com.couchbase.client.java.env.*;
import com.couchbase.client.java.env.*;
import com.couchbase.client.java.query.*;
import com.couchbase.client.java.query.*;
import java.util.logging.ConsoleHandler;
import java.util.logging.Handler;
import java.util.logging.Level;
import java.util.logging.Logger;

public class Test {
    
    public static void setLoggerLevels() {
        Logger logger = Logger.getLogger("com.couchbase.client");
        logger.setLevel(Level.FINE);
        for(Handler h : logger.getParent().getHandlers()) {
            if(h instanceof ConsoleHandler){
                h.setLevel(Level.FINE);
            }
        }        
    }

    public static String IP=null;
    public static String BUCKET=null;
                     
        
    
    public static void main(String[] args) {
        setLoggerLevels();
        BUCKET = args[0];
        IP=args[1];
        try {        

                CouchbaseEnvironment env = DefaultCouchbaseEnvironment.builder()
                    .queryEnabled(true) //that's the important part
                    .build();
            
                CouchbaseCluster cluster = CouchbaseCluster.create(env,IP );
                Bucket bucket = cluster.openBucket(BUCKET);
            
                System.out.println("query 1 begin");
                QueryResult res = bucket.query(Query.simple("SELECT * FROM "+BUCKET+" LIMIT 10"));
                System.out.println("query 1 end");
                System.out.println("query 2 begin");
                QueryResult res2 = bucket.query(Query.simple("SELECT * FROM "+BUCKET+" LIMIT 10"));
                System.out.println("query 2 end");

        } catch (Exception e) {
            e.printStackTrace();
        }
    }
}

The full cbq-dp4 results:

_time="2015-03-10T19:49:36+01:00" _level="INFO" _msg="Number of indexes 1" 
_time="2015-03-10T19:49:36+01:00" _level="INFO" _msg="Request View: http://IP:8092/bucket/_design/ddl_%23primary/_view/%23primary?limit=1001" 
_time="2015-03-10T19:49:36+01:00" _level="INFO" _msg="Number of entries fetched from the index 70" 
_time="2015-03-10T19:49:36+01:00" _level="INFO" _msg="Number of indexes 1" 
_time="2015-03-10T19:49:36+01:00" _level="INFO" _msg="Request View: http://IP:8092/bucket/_design/ddl_%23primary/_view/%23primary?limit=1001" 
_time="2015-03-10T19:49:36+01:00" _level="INFO" _msg="Number of entries fetched from the index 70" 
_time="2015-03-10T19:49:39+01:00" _level="INFO" _msg="Refreshing Indexes in keyspace bucket" 
_time="2015-03-10T19:49:39+01:00" _level="INFO" _msg="Found index #primary  on keyspace bucket" 
_time="2015-03-10T19:49:57+01:00" _level="INFO" _msg="Refreshing pool default" 
_time="2015-03-10T19:49:57+01:00" _level="INFO" _msg=" Checking keyspace bucket" 
2015/03/10 19:50:09 Warning: Finalizing a bucket with active connections.
2015/03/10 19:50:09 Warning: Finalizing a bucket with active connections.
2015/03/10 19:50:09 Warning: Finalizing a bucket with active connections.
_time="2015-03-10T19:50:39+01:00" _level="INFO" _msg="Refreshing Indexes in keyspace bucket" 
_time="2015-03-10T19:50:39+01:00" _level="INFO" _msg="Found index #primary  on keyspace bucket" 
_time="2015-03-10T19:50:57+01:00" _level="INFO" _msg="Refreshing pool default" 
_time="2015-03-10T19:50:57+01:00" _level="INFO" _msg=" Checking keyspace bucket" 

The full java output:

...
query 1 begin
query 1 end
query 2 begin
Mar 10, 2015 7:50:06 PM com.couchbase.client.core.endpoint.AbstractGenericHandler onKeepAliveFired
FINE: [/IP:11210][KeyValueEndpoint]: KeepAlive fired
Mar 10, 2015 7:50:06 PM com.couchbase.client.core.endpoint.AbstractGenericHandler onKeepAliveFired
FINE: [/IP:8092][ViewEndpoint]: KeepAlive fired
Mar 10, 2015 7:50:06 PM com.couchbase.client.core.endpoint.AbstractGenericHandler onKeepAliveFired
FINE: [/IP:8093][QueryEndpoint]: KeepAlive fired
Mar 10, 2015 7:50:36 PM com.couchbase.client.core.endpoint.AbstractGenericHandler onKeepAliveFired
FINE: [/IP:11210][KeyValueEndpoint]: KeepAlive fired
Mar 10, 2015 7:50:36 PM com.couchbase.client.core.endpoint.AbstractGenericHandler onKeepAliveFired
FINE: [/IP:8092][ViewEndpoint]: KeepAlive fired
Mar 10, 2015 7:50:36 PM com.couchbase.client.core.endpoint.AbstractGenericHandler onKeepAliveFired
FINE: [/IP:8093][QueryEndpoint]: KeepAlive fired
java.lang.RuntimeException: java.util.concurrent.TimeoutException
    at com.couchbase.client.java.util.Blocking.blockForSingle(Blocking.java:93)
    at com.couchbase.client.java.CouchbaseBucket.query(CouchbaseBucket.java:547)
    at com.couchbase.client.java.CouchbaseBucket.query(CouchbaseBucket.java:490)
    at Test.main(Test.java:62)
Caused by: java.util.concurrent.TimeoutException
    ... 4 more

Usage:

java Test bucket ip

It drops me TimeOutException with the second query.

Thank you very much!
Cheers,
Huhh

I forgot to write:
it works with an empty bucke, or if the bucket includes around 20 items.

still, no chance in reproducing it :fearful:
btw did you create a brand new project for that? in a previous post of yours I see that you included couchbase-client-1.4.8?

the logs are not at the FINEST level. Can you either increase the level or depend on log4j with the following log4j.properties content in your classpath:

# Root logger option
log4j.rootLogger=TRACE, stdout
log4j.sun.nio.ch.FileDispatcherImpl= FATAL, stdout

# Direct log messages to stdout
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.Target=System.out
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1}:%L - %m%n

At the most detailed level, the logs should contain traces looking like that:

2015-03-11 10:34:04 TRACE LoggingHandler:94 - [id: 0x5a54d945, /127.0.0.1:52950 => localhost/127.0.0.1:8093] RECEIVED(1024B)
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 0a 20 20 20 20 20 20 20 20 7d 2c 0a 20 20 20 20 |.        },.    |
|00000010| 20 20 20 20 7b 0a 20 20 20 20 20 20 20 20 20 20 |    {.          |
|00000020| 20 20 22 62 65 65 72 2d 73 61 6d 70 6c 65 22 3a |  "beer-sample":|

This will produce a lot of logs, so can you please upload the complete logs on a site like http://gist.github.com or http://pastebin.com and link to them here?
I hope this will help get to the bottom of this.

Also can you try to set the following setting on your environment:

CouchbaseEnvironment env = DefaultCouchbaseEnvironment.builder()
                    .queryEnabled(true)
                    .keepAliveInterval(0L) //disable Keep Alive
                    .build();
```

Edit: make sure the logs do contain detailled traces like the above. If not, switch to log4j as instructed. You can find further instructions on this [documentation page](http://docs.couchbase.com/developer/java-2.1/logging.html).

I had timeoutexception whden performing a query inside an observable operator on an Observable which was performing itself a query, on a single core machine. There was a deadlock because the compute pool would then have only a single thread. This thread is busy executing the operator. The operator tries to perform a query. This query cannot be completed because the thread is locked waiting.

I fixed this by increasing the pool size to a minimum of 2 to avoid any dead lock on single core machines.

Not sure this is the same case here, but it may help.

@vanadium actually that’s a good point. I wonder if we should force a hard minimum on the computation pool.

@vanadium I actually implemented lower pool boundaries for 2.1.2 (https://github.com/couchbase/couchbase-jvm-core/commit/2e625c8b917028136ded166ef44782d72463c1a9) so this can’t happen anymore. what do you think?

It seems good. I have set it to 4 by default on my side. 3 seems fine too. I think IO pool could be an auto growing thread pool, like the Scheduler.io() in RxJava.

Auto growing thread pool are great for IO. IO tasks are known to have Wait time several magnitudes higher than compute time. It allows optimal cpu usage, but has the counter part to be prone to thread spamming.

“Java concurrency in Practice” contains a nice formula to compute the ideal thread pool size depending on the wait / compute time ratio:
Ncpu= number of cpu core
Ucpu= target cpu usage between 0 and 1 inclusive
W/C = ratio of wait time to compute time
N threads = Ncpu * Ucpu * (1 + W/C)

Well in our case it is a little different because we use non blocking IO exclusively, and the thread pool size is passed down to netty where it multiplexes channels/sockets onto event loops.

Hello @daschl @vanadium
I am getting the timeout exception constantly … the sdk version i am using is 2.7.20 which has the MIN_POOL_SIZE change … couchbase query calls are api facing , so we do need to return data immediately, hence using toBlocking() . We have contacted couchbase customer support and implemented those changes and those havent helped either

{\"cause\":\"java.lang.RuntimeException: java.util.concurrent.TimeoutException\\n\\tat rx.exceptions.Exceptions.propagate(Exceptions.java:57) ~[rxjava-1.3.8.jar!/:1.3.8]\\n\\tat rx.observables.BlockingObservable.blockForSingle(BlockingObservable.java:463) ~[rxjava-1.3.8.jar!/:1.3.8]\\n\\tat rx.observables.BlockingObservable.singleOrDefault(BlockingObservable.java:372) ~[rxjava-1.3.8.jar!/:1.3.8]\

Any idea whats happening ?? any insights would be great , we are chasing this bug since last 2-3 months.