N1QL Query times out using parametrized values in IN clause

SQL++
, ,
1

Using couchbase server 4.1.0, java sdk 2.2.8 (also tried with 2.2.7) I have a query leveraging a secondary index which runs fine when I run my code locally and even via CBQ (CBQ takes about 30ms) on the Aws server however when running my app from AWS I get a TimeOutException it is only this query which is timing out others are not. I had a similar problem with 2.3.1 and resolved by goin to 2.2.7 its as if the query or maybe the index is the culprit see details below.

May be worth noting my couchbase setup has 3 buckets

Example Doc:

"bucketName": { "userName": "User_A", "MessageContent": "This is a message", "docType": "msg", "ParentMsgId": "1234", "MsgType": "test", "expireTimestamp": 1454975772613, "publishTimestamp": 1455322362028, "id": "145826845", "urls": [], "subject": "this is a subject", "type": 1, "GroupId": "Group_1" }

Secondary Index:

CREATE INDEX `indexName` ON `bucketName`(`ParentMsgId`,`docType`,`publishTimestamp`) USING GSI

Example Query extracted from N1qlQuery#n1ql()

{"statement": "select count(*) as msgCount from bucketName where ParentMsgId is not missing and docType = 'msg' and ParentMsgId IN $parentId and publishTimestamp between $startTime and $endTime ","$endTime":1470726861816, "$startTime":1470640461816, "$parenIds":["fa11845b-9ea5-4778-95fe-e7206843c69b"] }

Java Code

public static final String COUNT_STATEMENT = "select count(*) as count " +
            "from bucketName " +
            "where ParentMsgId is not missing " + 
            "and docType = 'msg' " +
            "and ParentMsgId IN $parentIds " + 
            "and publishTimestamp between $startTime and $endTime";

public int getCountForDuration(Long startTime, Long endTime, Collection<String> parentIds){
    List<String> idList = new ArrayList<>(parentIds);
    JsonObject placeHolders = JsonObject.create()
                                        .put("parentIds", JsonArray.from(idList))
                                        .put("startTime", startTime)
                                        .put("endTime", endTime);
    N1qlQuery query = N1qlQuery.parameterized(COUNT_STATEMENT, placeHolders)            
    N1qlQueryResult result = bucket.query(query);
    ...
}

Query Explain result

cbq> explain select count(*) as msgCount from bucketName where ParentMsgId is not missing and docType = 'msg' and ParentMsgId IN ["01b88f7f-4de6-4daa-9562-a2c902e818ad"] and publishTimestamp between 1466445409000 and 1466531809000;
{
    "requestID": "61afcf02-3b3d-4c8a-aec6-b76c4c1f7b17",
    "signature": "json",
    "results": [
        {
            "#operator": "Sequence",
            "~children": [
                {
                    "#operator": "IndexScan",
                    "index": "indexName",
                    "keyspace": "bucketName",
                    "namespace": "default",
                    "spans": [
                        {
                            "Range": {
                                "High": [
                                    "successor(\"01b88f7f-4de6-4daa-9562-a2c902e818ad\")"
                                ],
                                "Inclusion": 1,
                                "Low": [
                                    "\"01b88f7f-4de6-4daa-9562-a2c902e818ad\""
                                ]
                            }
                        }
                    ],
                    "using": "gsi"
                },
                {
                    "#operator": "Parallel",
                    "~child": {
                        "#operator": "Sequence",
                        "~children": [
                            {
                                "#operator": "Fetch",
                                "keyspace": "bucketName",
                                "namespace": "default"
                            },
                            {
                                "#operator": "Filter",
                                "condition": "(((((`bucketName`.`ParentMsgId`) is not missing) and ((`bucketName`.`docType`) = \"msg\")) and ((`bucketName`.`ParentMsgId`) in [\"01b88f7f-4de6-4daa-9562-a2c902e818ad\"])) and ((`bucketName`.`publishTimestamp`) between 1466445409000 and 1466531809000))"
                            },
                            {
                                "#operator": "InitialGroup",
                                "aggregates": [
                                    "count(*)"
                                ],
                                "group_keys": []
                            }
                        ]
                    }
                },
                {
                    "#operator": "IntermediateGroup",
                    "aggregates": [
                        "count(*)"
                    ],
                    "group_keys": []
                },
                {
                    "#operator": "FinalGroup",
                    "aggregates": [
                        "count(*)"
                    ],
                    "group_keys": []
                },
                {
                    "#operator": "Parallel",
                    "~child": {
                        "#operator": "Sequence",
                        "~children": [
                            {
                                "#operator": "InitialProject",
                                "result_terms": [
                                    {
                                        "as": "msgCount",
                                        "expr": "count(*)"
                                    }
                                ]
                            },
                            {
                                "#operator": "FinalProject"
                            }
                        ]
                    }
                }
            ]
        }
    ],
    "status": "success",
    "metrics": {
        "elapsedTime": "2.748194ms",
        "executionTime": "2.660232ms",
        "resultCount": 1,
        "resultSize": 3274
    }
}

Logs

java.lang.Thread.run(Thread.java:745)
org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:533)
org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:598)
org.eclipse.jetty.server.nio.BlockingChannelConnector$BlockingChannelEndPoint.run(BlockingChannelConnector.java:293)
org.eclipse.jetty.server.BlockingHttpConnection.handle(BlockingHttpConnection.java:50)
org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:218)
org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:582)
org.eclipse.jetty.server.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:919)
org.eclipse.jetty.server.HttpConnection.handleRequest(HttpConnection.java:441)
org.eclipse.jetty.server.Server.handle(Server.java:349)
org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:110)
org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:149)
org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:117)
org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:875)
org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:186)
org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:409)
org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:117)
org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:941)
org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:227)
org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:483)
org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:119)
org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:70)
org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:480)
org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:547)
org.apache.cxf.transport.servlet.AbstractHTTPServlet.service(AbstractHTTPServlet.java:201)
javax.servlet.http.HttpServlet.service(HttpServlet.java:693)
org.apache.cxf.transport.servlet.AbstractHTTPServlet.doGet(AbstractHTTPServlet.java:150)
org.apache.cxf.transport.servlet.AbstractHTTPServlet.handleRequest(AbstractHTTPServlet.java:225)
org.apache.cxf.transport.servlet.CXFNonSpringServlet.invoke(CXFNonSpringServlet.java:130)
org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:194)
org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:214)
org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:237)
org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121)
org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:262)
org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:94)
org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:58)
org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:89)
org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:168)
org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:96)
org.apache.cxf.service.invoker.AbstractInvoker.performInvocation(AbstractInvoker.java:180)
java.lang.reflect.Method.invoke(Method.java:498)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
biz.te2.core.services.beacon.impl.BeaconResource.getVenuesBeaconData(BeaconResource.java:105)
xxx.xxx.xxx.getBeaconHealthForRangeAndVenue(BeaconHealthServiceImpl.java:40)
xxx.xxx.xxx…getAllMessagesCount(BeaconHealthServiceImpl.java:80)
com.sun.proxy.$Proxy146.getMessageCountForDuration(Unknown Source)
org.apache.aries.proxy.impl.ProxyHandler.invoke(ProxyHandler.java:78)
org.apache.aries.proxy.impl.DefaultWrapper.invoke(DefaultWrapper.java:31)
org.apache.aries.proxy.impl.ProxyHandler$1.invoke(ProxyHandler.java:50)
java.lang.reflect.Method.invoke(Method.java:498)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
xxx.xxx.xxx.getMessageCountForDuration(MessageCouchbaseRepo.java:364)
xxx.xxx.xxx.getN1qlQueryRows(MessageCouchbaseRepo.java:372)
com.couchbase.client.java.CouchbaseBucket.query(CouchbaseBucket.java:582)
com.couchbase.client.java.CouchbaseBucket.query(CouchbaseBucket.java:656)
com.couchbase.client.java.util.Blocking.blockForSingle(Blocking.java:74)
java.util.concurrent.CountDownLatch.await(CountDownLatch.java:277)
java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1328)
java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1037)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)

2

Hi,

@prasad will help you with this…

3

Thanks @geraldss & @prasad much appreciated!

4

Hey @geraldss & @prasad any update or findings. Have any other users experienced anything similar?

5

Hi @mlblount45, I will get to it early next week.

6

Thanks @prasad appreciate it

7

Hi @mlblount45, do you see any other errors in query.log and index.log? If you don’t find any obvious errors, can you upload the collectinfo. thanks.

8

@prasad where would i find these logs? couchbase admin console server running couchbase?

9

Hi @mlblount45, these links have the details: ttp://developer.couchbase.com/documentation/server/4.5/clustersetup/ui-logs.html
http://developer.couchbase.com/documentation/server/4.5/cli/cbcollect-info-tool.html

10

@prasad how would you like me to provide you with the generated collectinfo .zip file?

11

Hi @mlblount45, you can upload to any cloud storage locations, and message me the path. Or, you can click the “collect information” button in the “log” tab in the web-console (which can upload it to Couchbase or a custom location). If uploading to couchbase site, let me know the cluster/customer name etc details you enter as part of collectinfo.

Also, can you reproduce the issue with query and indexer logging/tracing enabled. Then, look for any errors/warnings in the query/indexer logs.

To change query settings:

To change index settings:

curl -X POST http://localhost:9102/settings -u Administrator: -d '{“indexer.settings.scan_timeout”: }’
Timeout value is in millinseconds (default 2min).

curl -X POST http://localhost:9102/settings -u Administrator: -d '{“indexer.settings.log_level”: “trace”}’
Log level can also be set in web-console/settings.

If possible, truncate the old log file content, or get the timestamp before the query is issued.

-Prasad

12

Thanks @prasad I have uploaded here: https://s3.amazonaws.com/cb-customers/TE2/ file name is output_file.zip. I ran the query at 1473384995 epoch time. The bucket name that we are experiencing issues with in named “messages”

What did you mean by " (also, check if the timeout values are good)" what is a good value what is a poor value. on my machine this is what i had for timeout “timeout”: 0 same for index timeout not sure what to set it as.

also for anyone who sees this post in the future this -d@./z.json did work for me I had to use -d@n1ql_params.json instead.

13

@prasad I have made a minor adjustment to the index I have added the publishTimestamp to the indexer this increased the query from ~30ms to ~3ms when called from CBQ however the query still times out when called from java SDK. it feels like the SDK maybe the culprit perhaps.

14

You can isolate SDK issues by using curl or a script to post queries directly to cbq engine via HTTP.

15

Thanks @geraldss thats good to know. i’ll look into how to execute a curl call directly to CBQ. So since we are clearly by passing sdk all together if the times are fast via curl is it a decent chance that the SDK is the culprit?

16

Yep, it is a good way to isolate the possible cause.

17

@geraldss sorry to ask what feels like to be a simple question but do you see anything wrong with these curls. (the query works fine directly in CBQ. Ive tried single (') and double(") quotes around the query both return the same result.

ive encoded the = with %3D and I also tried escaping the double quotes same results

$ curl -v http://localhost:8093/query/service -d “statement%3Dselect experienceId from messages where experienceId is not missing and docType %3D “msg” and venueId %3D “SW_MCO” and experienceId IN [“001c11a9-6335-447d-b893-60d6a3637df7”] limit 2”

  • Trying ::1…
  • Connected to localhost (::1) port 8093 (#0)

POST /query/service HTTP/1.1
Host: localhost:8093
User-Agent: curl/7.43.0
Accept: /
Content-Length: 189
Content-Type: application/x-www-form-urlencoded

  • upload completely sent off: 189 out of 189 bytes
    < HTTP/1.1 400 Bad Request
    < Content-Length: 565
    < Content-Type: application/json; version=1.5.0
    < Date: Sat, 10 Sep 2016 20:19:52 GMT
    <
    {
    “requestID”: “b26f1d39-d3af-434e-b09e-65b367782b9e”,
    “errors”: [
    {
    “code”: 1065,
    “msg”: “Unrecognized parameter in request: statement=select experienceId from messages where experienceId is not missing and docType = msg and venueId = SW_MCO and experienceId IN [001c11a9-6335-447d-b893-60d6a3637df7] limit 2”
    }
    ],
    “status”: “fatal”,
    “metrics”: {
    “elapsedTime”: “59.672µs”,
    “executionTime”: “59.029µs”,
    “resultCount”: 0,
    “resultSize”: 0,
    “errorCount”: 1
    }
    }
18

Hi @mlblount45, I always use single quote for the curl parameter and use double quotes for the strings inside.

# curl -u Administrator:password http://localhost:8093/query/service -d 'statement=select count(*) from `beer-sample` where name is not missing and id in ["one", "two", "etc"] limit 2'
{
    "requestID": "fc4270af-591b-4e77-a057-1a887b678890",
    "signature": {
        "$1": "number"
    },
    "results": [
        {
            "$1": 0
        }
    ],
    "status": "success",
    "metrics": {
        "elapsedTime": "196.649189ms",
        "executionTime": "196.58408ms",
        "resultCount": 1,
        "resultSize": 31
    }
}
19

Thanks @keshav_m worked like a charm

@prasad & @geraldss using curl query ran in ~16ms the Query is so simple i would really be surprised if there was some issue with the SDK. Only thing different between this query and others is 1. This query uses the IN clause 2. this query is a different bucket than the other queries neither of these seem like problematic things.

20

Are you all set now?