Time taken in retrieving results in java

himanshu.mps · May 21, 2018, 10:09am

Hi,

This is in extension of this ticket: Issue while fetching data from couchbase

I have written standalone code but it takes around 200 msec to fetch the results on top of the query execution time (always).

import java.util.List;

import com.couchbase.client.java.AsyncBucket;
import com.couchbase.client.java.AsyncCluster;
import com.couchbase.client.java.CouchbaseAsyncCluster;
import com.couchbase.client.java.document.json.JsonObject;
import com.couchbase.client.java.env.CouchbaseEnvironment;
import com.couchbase.client.java.env.DefaultCouchbaseEnvironment;
import com.couchbase.client.java.query.AsyncN1qlQueryResult;
import com.couchbase.client.java.query.N1qlQuery;

public class NonSpringExample {

	public static void main(String... args) throws Exception {

		CouchbaseEnvironment environment = DefaultCouchbaseEnvironment.builder().queryTimeout(10000000).kvTimeout(10000000).searchTimeout(1000000).socketConnectTimeout(1000000000).managementTimeout(1000000000).connectTimeout(10000000).viewTimeout(10000000).autoreleaseAfter(10000).build();
		// Initialize the Connection
		AsyncCluster cluster = CouchbaseAsyncCluster.create(environment, "localhost");
		cluster.authenticate("pmc", "aaaa1234");
		AsyncBucket bucket = cluster.openBucket("pmc").toBlocking().single();
		// Perform a N1QL Query
		long startTime = System.currentTimeMillis();
		System.out.println("START TIME: " + startTime);
		List<JsonObject> list = bucket.query(N1qlQuery.simple("select * from pmc LIMIT 10"))
				.doOnNext(res -> res.info().forEach(t -> System.out.println("N1qlMetrics: " + t)))
				.flatMap(AsyncN1qlQueryResult::rows)
				.map(result -> {return result.value();})
				.toList()
				.toBlocking()
				.single();
		long endTime = System.currentTimeMillis();
		System.out.println("END TIME: " + endTime);
		System.out.println("Time taken: " + (endTime - startTime));
		System.out.println(list);
		
		cluster.disconnect();
	}
}

This is the output of this program.

START TIME: 1526897304202
N1qlMetrics: N1qlMetrics{resultCount=10, errorCount=0, warningCount=0, mutationCount=0, sortCount=0, resultSize=970, elapsedTime='287.5316ms', executionTime='287.0314ms'}
END TIME: 1526897304722
Time taken: 520
[{"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_100"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10001"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10002"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10003"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10004"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10005"}}]

Can someone help me so that the time taken in retrieval is less ?

pvarley · May 21, 2018, 11:49am

I think it would be useful to explain how to debug a case like this rather than jumping to the answer. For Couchbase Server to do a query the following happens:

The client encodes the query request
The requests is sent to a Query Services
The Query Services interprets the query and produces a plan
The Query Services executes the plan
The Query Service encodes the results
The the results are sent back to the client over the network
Client decode the response.

With the information provided, we know that steps 3 to 5 took 287.0314ms (executionTime), we also know that steps 1, 6, and 7 took 232.9686ms (Time taken - executionTime). In this case this is mostly likely to be network latency between the client and the node with the Query Service.

For executionTime more information can be find out what the Query Service has to do to answer the query, by using the EXPLAIN command, the UI has a nice visualization tool.

Looking at the query itself the plan on Couchbase Server 5.5.0-beta looks like this:

{
  "plan": {
    "#operator": "Sequence",
    "~children": [
      {
        "#operator": "Sequence",
        "~children": [
          {
            "#operator": "PrimaryScan3",
            "index": "#primary",
            "index_projection": {
              "primary_key": true
            },
            "keyspace": "pmc",
            "limit": "10",
            "namespace": "default",
            "using": "gsi"
          },
          {
            "#operator": "Fetch",
            "keyspace": "pmc",
            "namespace": "default"
          },
          {
            "#operator": "Parallel",
            "~child": {
              "#operator": "Sequence",
              "~children": [
                {
                  "#operator": "InitialProject",
                  "result_terms": [
                    {
                      "expr": "self",
                      "star": true
                    }
                  ]
                },
                {
                  "#operator": "FinalProject"
                }
              ]
            }
          }
        ]
      },
      {
        "#operator": "Limit",
        "expr": "10"
      }
    ]
  },
  "text": "select * from pmc LIMIT 10;"
}

As you can see it’s not the easiest thing to understand if you are new to Couchbase Server but let us look at the same thing using the visualization tool in the UI:

There are 4 stages to the query (you can click on each part to get more details) the main two are:

Index Scan: Using the primary index to get the keys of 10 documents.
Fetch: Getting the 10 documents from the Data Service nodes, this is because the query is using select * which can’t be covered by the index.

These steps are going to include network latency between the Query Service and Index Service, as well as latency between the Query Service and Data Service.

When the query is executed in the UI , more stats are produced:

Now we can see how long each stage of the query took inside the query service itself. In my case the query is taking 3.74ms to execute.

Back to the case at hand, the steps above can be used to debug the issue yourself or if preferred I can help further if the following answers and information can be provided:

What version of Couchbase Server is being used?
What is the network latency between the Client and the Query service?
What is the network latency between the Query server and the other two services (Data & Index)?
A screenshot of the query being executed in the UI with the plan view is provided so we can see where the time is being spent inside the Query service.

We generally recommend avoiding using select * queries as they’re always require fetching documents from the data-service, which is an extra network round trip. It’s better to select the fields required and use covering index.

The newer versions of Couchbase Server has more optimisations for queries that use limits and require fetching data from the Data service.

himanshu.mps · May 22, 2018, 5:31am

What is the network latency between the Client and the Query service?
What is the network latency between the Query server and the other two services (Data & Index)?

Do you think getting a traceroute between the servers will be helpful in getting the latency or do you need some other statistics for that ?

The newer versions of Couchbase Server has more optimisations for queries that use limits and require fetching data from the Data service.

Is there any page which I can refer to get more details on optimizations?

On my local I am running 5.1 community and on the production environment we have 5.1 enterprise.

himanshu.mps · May 22, 2018, 7:46am

I did install the 5.5.0-beta Enterprise version on my machine with 4 GB RAM allocated for couchbase alone. This is the couchbase info

CouchbaseEnvironment: {sslEnabled=false, sslKeystoreFile='null', sslTruststoreFile='null', sslKeystorePassword=false, sslTruststorePassword=false, sslKeystore=null, sslTruststore=null, bootstrapHttpEnabled=true, bootstrapCarrierEnabled=true, bootstrapHttpDirectPort=8091, bootstrapHttpSslPort=18091, bootstrapCarrierDirectPort=11210, bootstrapCarrierSslPort=11207, ioPoolSize=3, computationPoolSize=3, responseBufferSize=16384, requestBufferSize=16384, kvServiceEndpoints=1, viewServiceEndpoints=12, queryServiceEndpoints=12, searchServiceEndpoints=12, configPollInterval=2500, configPollFloorInterval=50, ioPool=NioEventLoopGroup, kvIoPool=null, viewIoPool=null, searchIoPool=null, queryIoPool=null, coreScheduler=CoreScheduler, memcachedHashingStrategy=DefaultMemcachedHashingStrategy, eventBus=DefaultEventBus, packageNameAndVersion=couchbase-java-client/2.5.5 (git: 2.5.5, core: 1.5.5), retryStrategy=BestEffort, maxRequestLifetime=75000, retryDelay=ExponentialDelay{growBy 1.0 MICROSECONDS, powers of 2; lower=100, upper=100000}, reconnectDelay=ExponentialDelay{growBy 1.0 MILLISECONDS, powers of 2; lower=32, upper=4096}, observeIntervalDelay=ExponentialDelay{growBy 1.0 MICROSECONDS, powers of 2; lower=10, upper=100000}, keepAliveInterval=30000, continuousKeepAliveEnabled=true, keepAliveErrorThreshold=4, keepAliveTimeout=2500, autoreleaseAfter=10000, bufferPoolingEnabled=true, tcpNodelayEnabled=true, mutationTokensEnabled=false, socketConnectTimeout=1000000000, callbacksOnIoPool=false, disconnectTimeout=25000, requestBufferWaitStrategy=com.couchbase.client.core.env.DefaultCoreEnvironment$2@40e6dfe1, certAuthEnabled=false, coreSendHook=null, forceSaslPlain=false, queryTimeout=10000000, viewTimeout=10000000, searchTimeout=1000000, analyticsTimeout=75000, kvTimeout=10000000, connectTimeout=10000000, dnsSrvEnabled=false}

This is the result from executing the query on couchbase console. This is the plan text as the image is very small

{
  "#operator": "Sequence",
  "#stats": {
    "#phaseSwitches": 1
  },
  "~children": [
    {
      "#operator": "Authorize",
      "#stats": {
        "#phaseSwitches": 3,
        "servTime": "27.9986ms"
      },
      "privileges": {
        "List": [
          {
            "Target": "default:pmc",
            "Priv": 7
          }
        ]
      },
      "~child": {
        "#operator": "Sequence",
        "#stats": {
          "#phaseSwitches": 1
        },
        "~children": [
          {
            "#operator": "Sequence",
            "#stats": {
              "#phaseSwitches": 2,
              "state": "running"
            },
            "~children": [
              {
                "#operator": "PrimaryScan3",
                "#stats": {
                  "#itemsOut": 10,
                  "#phaseSwitches": 43,
                  "servTime": "24.0123ms"
                },
                "index": "pmc-index",
                "index_projection": {
                  "primary_key": true
                },
                "keyspace": "pmc",
                "limit": "10",
                "namespace": "default",
                "using": "gsi",
                "#time_normal": "00:00.0240",
                "#time_absolute": 0.0240123
              },
              {
                "#operator": "Fetch",
                "#stats": {
                  "#itemsIn": 10,
                  "#itemsOut": 10,
                  "#phaseSwitches": 45,
                  "kernTime": "24.0123ms",
                  "servTime": "12.0015ms"
                },
                "keyspace": "pmc",
                "namespace": "default",
                "#time_normal": "00:00.0120",
                "#time_absolute": 0.0120015
              },
              {
                "#operator": "Sequence",
                "#stats": {
                  "#phaseSwitches": 2,
                  "state": "running"
                },
                "~children": [
                  {
                    "#operator": "InitialProject",
                    "#stats": {
                      "#itemsIn": 10,
                      "#itemsOut": 10,
                      "#phaseSwitches": 37,
                      "kernTime": "36.0138ms"
                    },
                    "result_terms": [
                      {
                        "expr": "self",
                        "star": true
                      }
                    ]
                  },
                  {
                    "#operator": "FinalProject",
                    "#stats": {
                      "#itemsIn": 10,
                      "#itemsOut": 10,
                      "#phaseSwitches": 21
                    }
                  }
                ]
              }
            ]
          },
          {
            "#operator": "Limit",
            "#stats": {
              "#itemsIn": 10,
              "#itemsOut": 10,
              "#phaseSwitches": 31
            },
            "expr": "10"
          }
        ]
      },
      "#time_normal": "00:00.0279",
      "#time_absolute": 0.0279986
    },
    {
      "#operator": "Stream",
      "#stats": {
        "#itemsIn": 10,
        "#itemsOut": 10,
        "#phaseSwitches": 43,
        "kernTime": "64.0124ms"
      }
    }
  ],
  "~versions": [
    "2.0.0-N1QL",
    "5.5.0-2473-enterprise"
  ]
}

This is the result after executing it with the java code. All the services are running on localhost and I do not think there is any latency.

START TIME: 1526974755429
N1qlMetrics: N1qlMetrics{resultCount=10, errorCount=0, warningCount=0, mutationCount=0, sortCount=0, resultSize=964, elapsedTime='6.5012ms', executionTime='6.5012ms'}
END TIME: 1526974755664
Time taken: 235
[{"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_100"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1001"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1002"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1003"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1004"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1005"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1006"}}]

himanshu.mps · May 22, 2018, 8:12am

When the same query is executed using python, it is taking much less time.

Python Code:

from couchbase.cluster import Cluster
from couchbase.cluster import PasswordAuthenticator
from couchbase.n1ql import N1QLQuery
from datetime import datetime
cluster = Cluster('couchbase://localhost')
authenticator = PasswordAuthenticator('pmc', 'aaaa1234')
cluster.authenticate(authenticator)
cb = cluster.open_bucket('pmc')
print "Query: start time: " + str(datetime.now())
row_iter = cb.n1ql_query(N1QLQuery('SELECT META(`pmc`).id AS _ID, META(`pmc`).cas AS _CAS, `pmc`.* FROM `pmc` LIMIT 10'))
print "Query: end time: " + str(datetime.now())
print "Print Data: Start time: " + str(datetime.now())	
for row in row_iter: 
	print row
print "Print Data: End time: " + str(datetime.now())	
# {u'name': u'Arthur'}

Python Result:

D:\gpc\testPython>c:\Python27\python.exe testPython.py
Query: start time: 2018-05-22 13:38:12.106000
Query: end time: 2018-05-22 13:38:12.141000
Print Data: Start time: 2018-05-22 13:38:12.144000
{u'javaClass': u'com.test.gpc.api.vo.Product', u'_ID': u'reactive_product_1', u'glbl_holder_prod_id': u'glblHolderProdId_1', u'_CAS': 1526976068505763840L}
{u'javaClass': u'com.test.gpc.api.vo.Product', u'_ID': u'reactive_product_10', u'glbl_holder_prod_id': u'glblHolderProdId_10', u'_CAS': 1526976068516118528L}
{u'javaClass': u'com.test.gpc.api.vo.Product', u'_ID': u'reactive_product_100', u'glbl_holder_prod_id': u'glblHolderProdId_100', u'_CAS': 1526976068649418752L}
{u'javaClass': u'com.test.gpc.api.vo.Product', u'_ID': u'reactive_product_1000', u'glbl_holder_prod_id': u'glblHolderProdId_1000', u'_CAS': 1526976071571603456L}
{u'javaClass': u'com.test.gpc.api.vo.Product', u'_ID': u'reactive_product_10000', u'glbl_holder_prod_id': u'glblHolderProdId_10000', u'_CAS': 1526976086678831104L}
{u'javaClass': u'com.test.gpc.api.vo.Product', u'_ID': u'reactive_product_10001', u'glbl_holder_prod_id': u'glblHolderProdId_10001', u'_CAS': 1526976086680862720L}
{u'javaClass': u'com.test.gpc.api.vo.Product', u'_ID': u'reactive_product_10002', u'glbl_holder_prod_id': u'glblHolderProdId_10002', u'_CAS': 1526976086683615232L}
{u'javaClass': u'com.test.gpc.api.vo.Product', u'_ID': u'reactive_product_10003', u'glbl_holder_prod_id': u'glblHolderProdId_10003', u'_CAS': 1526976086687023104L}
{u'javaClass': u'com.test.gpc.api.vo.Product', u'_ID': u'reactive_product_10004', u'glbl_holder_prod_id': u'glblHolderProdId_10004', u'_CAS': 1526976086690365440L}
{u'javaClass': u'com.test.gpc.api.vo.Product', u'_ID': u'reactive_product_10005', u'glbl_holder_prod_id': u'glblHolderProdId_10005', u'_CAS': 1526976086691282944L}
Print Data: End time: 2018-05-22 13:38:12.226000

himanshu.mps · May 22, 2018, 10:52am

Am I making any fundamental mistake which is leading to this erratic scenario ?

pvarley · May 22, 2018, 11:53am

Is there any page which I can refer to get more details on optimizations?

There are a few different guides on generic N1QL optimizations and some of the improvements in Couchbase Server 5.5:

Do you think getting a traceroute between the servers will be helpful in getting the latency or do you need some other statistics for that ?

Traceroute or ping will both give you a rough idea of latency but given that everything is running locally, this is not needed any more.

This is the result after executing it with the java code. All the services are running on localhost and I do not think there is any latency.

Given that everything is local then the latency should be very low.

The main focus now seems to be that Java is taking 235ms compare to Python where it’s taking 35ms.

We can see from the N1QLMetrics the Query servers was extremely fast as 6.5012ms.

N1qlMetrics: N1qlMetrics{resultCount=10, errorCount=0, warningCount=0, mutationCount=0, sortCount=0, resultSize=964, elapsedTime='6.5012ms', executionTime='6.5012ms'}

The rest of the time was either on the network stack or in the Java SDK. Given that it’s over localhost and the Python SDK behave quickly in the same environment . It points to time being spent in the Java SDK.

What version of the Java SDK is being used?
It would be useful to enabled the Java SDK logs and to review them - Collecting Information

@daschl Can you help out here with the Java SDK?

Finally you might be interested in the open Tracing support that is being added into Couchbase Server 5.5 which will make it easier to debug problems like these:

Response Time Observability with the Java SDK

himanshu.mps · May 23, 2018, 5:44am

@pvarley @daschl

I saw some time in Queryconfig being take. So I added queryServiceConfig(QueryServiceConfig.create(10, 100)) to the couchbase environment. Also I enabled trace logs to see what is taking the time. I couldn’t figure it out further.

Java Code:

import java.util.List;
import java.util.concurrent.TimeUnit;

import org.slf4j.LoggerFactory;
import org.slf4j.Logger;

import com.couchbase.client.core.env.QueryServiceConfig;
import com.couchbase.client.core.time.Delay;
import com.couchbase.client.java.AsyncBucket;
import com.couchbase.client.java.AsyncCluster;
import com.couchbase.client.java.CouchbaseAsyncCluster;
import com.couchbase.client.java.document.json.JsonObject;
import com.couchbase.client.java.env.CouchbaseEnvironment;
import com.couchbase.client.java.env.DefaultCouchbaseEnvironment;
import com.couchbase.client.java.query.AsyncN1qlQueryResult;
import com.couchbase.client.java.query.N1qlParams;
import com.couchbase.client.java.query.N1qlQuery;

public class NonSpringExample {
	private static final Logger logger = LoggerFactory.getLogger(NonSpringExample.class);

	public static void main(String... args) throws Exception {

		System.setProperty("com.couchbase.queryEnabled", "true");
		logger.info("***************** ASYNC *****************");
		CouchbaseEnvironment environment = DefaultCouchbaseEnvironment.builder().queryTimeout(10000000).kvTimeout(10000000).searchTimeout(1000000).socketConnectTimeout(1000000000).managementTimeout(1000000000).connectTimeout(10000000).viewTimeout(10000000).autoreleaseAfter(10000).queryServiceConfig(QueryServiceConfig.create(10, 100)).build();
		// Initialize the Connection
		AsyncCluster asyncCluster = CouchbaseAsyncCluster.create(environment,"localhost");
		asyncCluster.authenticate("pmc", "aaaa1234");
		AsyncBucket asyncBucket = asyncCluster.openBucket("pmc").toBlocking().single();
		// Perform a N1QL Query
		Thread.sleep(10000);
		long startTime = System.currentTimeMillis();
		N1qlParams params = N1qlParams.build().adhoc(true).pretty(false);
		logger.info("********** START TIME: " + startTime);
		List<JsonObject> asyncList = asyncBucket.query(N1qlQuery.simple("select * from pmc LIMIT 10", params))
				.doOnNext(res -> res.info().forEach(t -> logger.info("N1qlMetrics: " + t)))
				.flatMap(AsyncN1qlQueryResult::rows)
				.map(result -> {return result.value();})
				.toList()
				.toBlocking()
				.single();
		long endTime = System.currentTimeMillis();
		logger.info("********** END TIME: " + endTime);
		logger.info("********** Time taken: " + (endTime - startTime));
		logger.info(asyncList.toString());
		asyncList.clear();
		asyncList = null;
		asyncCluster.disconnect();
	}
}

Couchbase environment:

2018-05-23 11:04:58.110 INFO --- [ main] com.couchbase.client.core.CouchbaseCore : CouchbaseEnvironment: {sslEnabled=false, sslKeystoreFile='null', sslTruststoreFile='null', sslKeystorePassword=false, sslTruststorePassword=false, sslKeystore=null, sslTruststore=null, bootstrapHttpEnabled=true, bootstrapCarrierEnabled=true, bootstrapHttpDirectPort=8091, bootstrapHttpSslPort=18091, bootstrapCarrierDirectPort=11210, bootstrapCarrierSslPort=11207, ioPoolSize=3, computationPoolSize=3, responseBufferSize=16384, requestBufferSize=16384, kvServiceEndpoints=1, viewServiceEndpoints=12, queryServiceEndpoints=12, searchServiceEndpoints=12, configPollInterval=2500, configPollFloorInterval=50, ioPool=NioEventLoopGroup, kvIoPool=null, viewIoPool=null, searchIoPool=null, queryIoPool=null, coreScheduler=CoreScheduler, memcachedHashingStrategy=DefaultMemcachedHashingStrategy, eventBus=DefaultEventBus, packageNameAndVersion=couchbase-java-client/2.5.8 (git: 2.5.8, core: 1.5.8), retryStrategy=BestEffort, maxRequestLifetime=75000, retryDelay=ExponentialDelay{growBy 1.0 MICROSECONDS, powers of 2; lower=100, upper=100000}, reconnectDelay=ExponentialDelay{growBy 1.0 MILLISECONDS, powers of 2; lower=32, upper=4096}, observeIntervalDelay=FixedDelay{1 MICROSECONDS}, keepAliveInterval=30000, continuousKeepAliveEnabled=true, keepAliveErrorThreshold=4, keepAliveTimeout=2500, autoreleaseAfter=10000, bufferPoolingEnabled=true, tcpNodelayEnabled=true, mutationTokensEnabled=false, socketConnectTimeout=1000000000, callbacksOnIoPool=false, disconnectTimeout=25000, requestBufferWaitStrategy=com.couchbase.client.core.env.DefaultCoreEnvironment$2@5d740a0f, certAuthEnabled=false, coreSendHook=null, forceSaslPlain=false, queryTimeout=10000000, viewTimeout=10000000, searchTimeout=1000000, analyticsTimeout=75000, kvTimeout=10000000, connectTimeout=10000000, dnsSrvEnabled=false}

Trace Logs:

  2018-05-23 11:05:13.793  INFO   --- [           main] NonSpringExample                         : ********** START TIME: 1527053713792
2018-05-23 11:05:13.835 TRACE   --- [      cb-io-1-3] c.c.c.d.i.n.h.logging.LoggingHandler     : [id: 0x37793806, L:/127.0.0.1:64326 - R:/127.0.0.1:8093] WRITE: 357B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 50 4f 53 54 20 2f 71 75 65 72 79 20 48 54 54 50 |POST /query HTTP|
|00000010| 2f 31 2e 31 0d 0a 55 73 65 72 2d 41 67 65 6e 74 |/1.1..User-Agent|
|00000020| 3a 20 63 6f 75 63 68 62 61 73 65 2d 6a 61 76 61 |: couchbase-java|
|00000030| 2d 63 6c 69 65 6e 74 2f 32 2e 35 2e 38 20 28 67 |-client/2.5.8 (g|
|00000040| 69 74 3a 20 32 2e 35 2e 38 2c 20 63 6f 72 65 3a |it: 2.5.8, core:|
|00000050| 20 31 2e 35 2e 38 29 20 28 57 69 6e 64 6f 77 73 | 1.5.8) (Windows|
|00000060| 20 31 30 2f 31 30 2e 30 20 61 6d 64 36 34 3b 20 | 10/10.0 amd64; |
|00000070| 4a 61 76 61 20 48 6f 74 53 70 6f 74 28 54 4d 29 |Java HotSpot(TM)|
|00000080| 20 36 34 2d 42 69 74 20 53 65 72 76 65 72 20 56 | 64-Bit Server V|
|00000090| 4d 20 31 2e 38 2e 30 5f 31 34 31 2d 62 31 35 29 |M 1.8.0_141-b15)|
|000000a0| 0d 0a 43 6f 6e 74 65 6e 74 2d 54 79 70 65 3a 20 |..Content-Type: |
|000000b0| 61 70 70 6c 69 63 61 74 69 6f 6e 2f 6a 73 6f 6e |application/json|
|000000c0| 0d 0a 43 6f 6e 74 65 6e 74 2d 4c 65 6e 67 74 68 |..Content-Length|
|000000d0| 3a 20 38 30 0d 0a 48 6f 73 74 3a 20 31 32 37 2e |: 80..Host: 127.|
|000000e0| 30 2e 30 2e 31 3a 38 30 39 33 0d 0a 41 75 74 68 |0.0.1:8093..Auth|
|000000f0| 6f 72 69 7a 61 74 69 6f 6e 3a 20 42 61 73 69 63 |orization: Basic|
|00000100| 20 63 47 31 6a 4f 6b 46 74 5a 58 67 78 4d 6a 4d | cG1jOkFtZXgxMjM|
|00000110| 30 0d 0a 0d 0a 7b 22 73 74 61 74 65 6d 65 6e 74 |0....{"statement|
|00000120| 22 3a 22 73 65 6c 65 63 74 20 2a 20 66 72 6f 6d |":"select * from|
|00000130| 20 70 6d 63 20 4c 49 4d 49 54 20 31 30 22 2c 22 | pmc LIMIT 10","|
|00000140| 70 72 65 74 74 79 22 3a 66 61 6c 73 65 2c 22 74 |pretty":false,"t|
|00000150| 69 6d 65 6f 75 74 22 3a 22 31 30 30 30 30 30 30 |imeout":"1000000|
|00000160| 30 6d 73 22 7d                                  |0ms"}           |
+--------+-------------------------------------------------+----------------+
2018-05-23 11:05:13.835 TRACE   --- [      cb-io-1-3] c.c.c.d.i.n.h.logging.LoggingHandler     : [id: 0x37793806, L:/127.0.0.1:64326 - R:/127.0.0.1:8093] FLUSH
2018-05-23 11:05:13.846 TRACE   --- [      cb-io-1-3] c.c.c.d.i.n.h.logging.LoggingHandler     : [id: 0x37793806, L:/127.0.0.1:64326 - R:/127.0.0.1:8093] READ: 1024B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 48 54 54 50 2f 31 2e 31 20 32 30 30 20 4f 4b 0d |HTTP/1.1 200 OK.|
|00000010| 0a 43 6f 6e 74 65 6e 74 2d 4c 65 6e 67 74 68 3a |.Content-Length:|
|00000020| 20 31 32 31 30 0d 0a 43 6f 6e 74 65 6e 74 2d 54 | 1210..Content-T|
|00000030| 79 70 65 3a 20 61 70 70 6c 69 63 61 74 69 6f 6e |ype: application|
|00000040| 2f 6a 73 6f 6e 3b 20 76 65 72 73 69 6f 6e 3d 32 |/json; version=2|
|00000050| 2e 30 2e 30 2d 4e 31 51 4c 0d 0a 44 61 74 65 3a |.0.0-N1QL..Date:|
|00000060| 20 57 65 64 2c 20 32 33 20 4d 61 79 20 32 30 31 | Wed, 23 May 201|
|00000070| 38 20 30 35 3a 33 35 3a 31 33 20 47 4d 54 0d 0a |8 05:35:13 GMT..|
|00000080| 0d 0a 7b 0a 22 72 65 71 75 65 73 74 49 44 22 3a |..{."requestID":|
|00000090| 20 22 66 64 31 61 38 30 31 66 2d 30 38 31 39 2d | "fd1a801f-0819-|
|000000a0| 34 39 30 66 2d 61 61 35 31 2d 35 37 65 35 30 37 |490f-aa51-57e507|
|000000b0| 65 66 34 65 35 32 22 2c 0a 22 73 69 67 6e 61 74 |ef4e52",."signat|
|000000c0| 75 72 65 22 3a 20 7b 22 2a 22 3a 22 2a 22 7d 2c |ure": {"*":"*"},|
|000000d0| 0a 22 72 65 73 75 6c 74 73 22 3a 20 5b 0a 7b 22 |."results": [.{"|
|000000e0| 70 6d 63 22 3a 7b 22 67 6c 62 6c 5f 68 6f 6c 64 |pmc":{"glbl_hold|
|000000f0| 65 72 5f 70 72 6f 64 5f 69 64 22 3a 22 67 6c 62 |er_prod_id":"glb|
|00000100| 6c 48 6f 6c 64 65 72 50 72 6f 64 49 64 5f 31 22 |lHolderProdId_1"|
|00000110| 2c 22 6a 61 76 61 43 6c 61 73 73 22 3a 22 63 6f |,"javaClass":"co|
|00000120| 6d 2e 74 65 73 74 2e 67 70 63 2e 61 70 69 2e 76 |m.test.gpc.api.v|
|00000130| 6f 2e 50 72 6f 64 75 63 74 22 7d 7d 2c 0a 7b 22 |o.Product"}},.{"|
|00000140| 70 6d 63 22 3a 7b 22 67 6c 62 6c 5f 68 6f 6c 64 |pmc":{"glbl_hold|
|00000150| 65 72 5f 70 72 6f 64 5f 69 64 22 3a 22 67 6c 62 |er_prod_id":"glb|
|00000160| 6c 48 6f 6c 64 65 72 50 72 6f 64 49 64 5f 31 30 |lHolderProdId_10|
|00000170| 22 2c 22 6a 61 76 61 43 6c 61 73 73 22 3a 22 63 |","javaClass":"c|
|00000180| 6f 6d 2e 74 65 73 74 2e 67 70 63 2e 61 70 69 2e |om.test.gpc.api.|
|00000190| 76 6f 2e 50 72 6f 64 75 63 74 22 7d 7d 2c 0a 7b |vo.Product"}},.{|
|000001a0| 22 70 6d 63 22 3a 7b 22 67 6c 62 6c 5f 68 6f 6c |"pmc":{"glbl_hol|
|000001b0| 64 65 72 5f 70 72 6f 64 5f 69 64 22 3a 22 67 6c |der_prod_id":"gl|
|000001c0| 62 6c 48 6f 6c 64 65 72 50 72 6f 64 49 64 5f 31 |blHolderProdId_1|
|000001d0| 30 30 22 2c 22 6a 61 76 61 43 6c 61 73 73 22 3a |00","javaClass":|
|000001e0| 22 63 6f 6d 2e 74 65 73 74 2e 67 70 63 2e 61 70 |"com.test.gpc.ap|
|000001f0| 69 2e 76 6f 2e 50 72 6f 64 75 63 74 22 7d 7d 2c |i.vo.Product"}},|
|00000200| 0a 7b 22 70 6d 63 22 3a 7b 22 67 6c 62 6c 5f 68 |.{"pmc":{"glbl_h|
|00000210| 6f 6c 64 65 72 5f 70 72 6f 64 5f 69 64 22 3a 22 |older_prod_id":"|
|00000220| 67 6c 62 6c 48 6f 6c 64 65 72 50 72 6f 64 49 64 |glblHolderProdId|
|00000230| 5f 31 30 30 30 22 2c 22 6a 61 76 61 43 6c 61 73 |_1000","javaClas|
|00000240| 73 22 3a 22 63 6f 6d 2e 74 65 73 74 2e 67 70 63 |s":"com.test.gpc|
|00000250| 2e 61 70 69 2e 76 6f 2e 50 72 6f 64 75 63 74 22 |.api.vo.Product"|
|00000260| 7d 7d 2c 0a 7b 22 70 6d 63 22 3a 7b 22 67 6c 62 |}},.{"pmc":{"glb|
|00000270| 6c 5f 68 6f 6c 64 65 72 5f 70 72 6f 64 5f 69 64 |l_holder_prod_id|
|00000280| 22 3a 22 67 6c 62 6c 48 6f 6c 64 65 72 50 72 6f |":"glblHolderPro|
|00000290| 64 49 64 5f 31 30 30 30 30 22 2c 22 6a 61 76 61 |dId_10000","java|
|000002a0| 43 6c 61 73 73 22 3a 22 63 6f 6d 2e 74 65 73 74 |Class":"com.test|
|000002b0| 2e 67 70 63 2e 61 70 69 2e 76 6f 2e 50 72 6f 64 |.gpc.api.vo.Prod|
|000002c0| 75 63 74 22 7d 7d 2c 0a 7b 22 70 6d 63 22 3a 7b |uct"}},.{"pmc":{|
|000002d0| 22 67 6c 62 6c 5f 68 6f 6c 64 65 72 5f 70 72 6f |"glbl_holder_pro|
|000002e0| 64 5f 69 64 22 3a 22 67 6c 62 6c 48 6f 6c 64 65 |d_id":"glblHolde|
|000002f0| 72 50 72 6f 64 49 64 5f 31 30 30 30 31 22 2c 22 |rProdId_10001","|
|00000300| 6a 61 76 61 43 6c 61 73 73 22 3a 22 63 6f 6d 2e |javaClass":"com.|
|00000310| 74 65 73 74 2e 67 70 63 2e 61 70 69 2e 76 6f 2e |test.gpc.api.vo.|
|00000320| 50 72 6f 64 75 63 74 22 7d 7d 2c 0a 7b 22 70 6d |Product"}},.{"pm|
|00000330| 63 22 3a 7b 22 67 6c 62 6c 5f 68 6f 6c 64 65 72 |c":{"glbl_holder|
|00000340| 5f 70 72 6f 64 5f 69 64 22 3a 22 67 6c 62 6c 48 |_prod_id":"glblH|
|00000350| 6f 6c 64 65 72 50 72 6f 64 49 64 5f 31 30 30 30 |olderProdId_1000|
|00000360| 32 22 2c 22 6a 61 76 61 43 6c 61 73 73 22 3a 22 |2","javaClass":"|
|00000370| 63 6f 6d 2e 74 65 73 74 2e 67 70 63 2e 61 70 69 |com.test.gpc.api|
|00000380| 2e 76 6f 2e 50 72 6f 64 75 63 74 22 7d 7d 2c 0a |.vo.Product"}},.|
|00000390| 7b 22 70 6d 63 22 3a 7b 22 67 6c 62 6c 5f 68 6f |{"pmc":{"glbl_ho|
|000003a0| 6c 64 65 72 5f 70 72 6f 64 5f 69 64 22 3a 22 67 |lder_prod_id":"g|
|000003b0| 6c 62 6c 48 6f 6c 64 65 72 50 72 6f 64 49 64 5f |lblHolderProdId_|
|000003c0| 31 30 30 30 33 22 2c 22 6a 61 76 61 43 6c 61 73 |10003","javaClas|
|000003d0| 73 22 3a 22 63 6f 6d 2e 74 65 73 74 2e 67 70 63 |s":"com.test.gpc|
|000003e0| 2e 61 70 69 2e 76 6f 2e 50 72 6f 64 75 63 74 22 |.api.vo.Product"|
|000003f0| 7d 7d 2c 0a 7b 22 70 6d 63 22 3a 7b 22 67 6c 62 |}},.{"pmc":{"glb|
+--------+-------------------------------------------------+----------------+
2018-05-23 11:05:13.856 TRACE   --- [      cb-io-1-3] c.c.c.c.endpoint.AbstractGenericHandler  : [/127.0.0.1:8093][QueryEndpoint]: Started decoding of GenericQueryRequest{observable=rx.subjects.AsyncSubject@b433f35, bucket='pmc'}
2018-05-23 11:05:13.880 TRACE   --- [      cb-io-1-3] c.c.c.c.e.q.p.YasjlQueryResponseParser   : Started receiving results for requestId fd1a801f-0819-490f-aa51-57e507ef4e52
2018-05-23 11:05:13.882 TRACE   --- [      cb-io-1-3] c.c.c.c.e.q.p.YasjlQueryResponseParser   : Still expecting more data for requestId fd1a801f-0819-490f-aa51-57e507ef4e52
2018-05-23 11:05:13.882 TRACE   --- [      cb-io-1-3] c.c.c.d.i.n.h.logging.LoggingHandler     : [id: 0x37793806, L:/127.0.0.1:64326 - R:/127.0.0.1:8093] READ: 316B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 6c 5f 68 6f 6c 64 65 72 5f 70 72 6f 64 5f 69 64 |l_holder_prod_id|
|00000010| 22 3a 22 67 6c 62 6c 48 6f 6c 64 65 72 50 72 6f |":"glblHolderPro|
|00000020| 64 49 64 5f 31 30 30 30 34 22 2c 22 6a 61 76 61 |dId_10004","java|
|00000030| 43 6c 61 73 73 22 3a 22 63 6f 6d 2e 74 65 73 74 |Class":"com.test|
|00000040| 2e 67 70 63 2e 61 70 69 2e 76 6f 2e 50 72 6f 64 |.gpc.api.vo.Prod|
|00000050| 75 63 74 22 7d 7d 2c 0a 7b 22 70 6d 63 22 3a 7b |uct"}},.{"pmc":{|
|00000060| 22 67 6c 62 6c 5f 68 6f 6c 64 65 72 5f 70 72 6f |"glbl_holder_pro|
|00000070| 64 5f 69 64 22 3a 22 67 6c 62 6c 48 6f 6c 64 65 |d_id":"glblHolde|
|00000080| 72 50 72 6f 64 49 64 5f 31 30 30 30 35 22 2c 22 |rProdId_10005","|
|00000090| 6a 61 76 61 43 6c 61 73 73 22 3a 22 63 6f 6d 2e |javaClass":"com.|
|000000a0| 74 65 73 74 2e 67 70 63 2e 61 70 69 2e 76 6f 2e |test.gpc.api.vo.|
|000000b0| 50 72 6f 64 75 63 74 22 7d 7d 0a 5d 2c 0a 22 73 |Product"}}.],."s|
|000000c0| 74 61 74 75 73 22 3a 20 22 73 75 63 63 65 73 73 |tatus": "success|
|000000d0| 22 2c 0a 22 6d 65 74 72 69 63 73 22 3a 20 7b 22 |",."metrics": {"|
|000000e0| 65 6c 61 70 73 65 64 54 69 6d 65 22 3a 20 22 36 |elapsedTime": "6|
|000000f0| 2e 39 39 39 33 6d 73 22 2c 22 65 78 65 63 75 74 |.9993ms","execut|
|00000100| 69 6f 6e 54 69 6d 65 22 3a 20 22 36 2e 39 39 39 |ionTime": "6.999|
|00000110| 33 6d 73 22 2c 22 72 65 73 75 6c 74 43 6f 75 6e |3ms","resultCoun|
|00000120| 74 22 3a 20 31 30 2c 22 72 65 73 75 6c 74 53 69 |t": 10,"resultSi|
|00000130| 7a 65 22 3a 20 39 37 30 7d 0a 7d 0a             |ze": 970}.}.    |
+--------+-------------------------------------------------+----------------+
2018-05-23 11:05:13.886 TRACE   --- [      cb-io-1-3] c.c.c.c.e.q.p.YasjlQueryResponseParser   : Received last chunk and completed parsing for requestId fd1a801f-0819-490f-aa51-57e507ef4e52
2018-05-23 11:05:13.886 TRACE   --- [      cb-io-1-3] c.c.c.c.endpoint.AbstractGenericHandler  : [/127.0.0.1:8093][QueryEndpoint]: Finished decoding of GenericQueryRequest{observable=rx.subjects.AsyncSubject@b433f35, bucket='pmc'}
2018-05-23 11:05:13.887 TRACE   --- [      cb-io-1-3] c.c.c.d.i.n.h.logging.LoggingHandler     : [id: 0x37793806, L:/127.0.0.1:64326 - R:/127.0.0.1:8093] READ COMPLETE
2018-05-23 11:05:13.915  INFO   --- [-computations-1] NonSpringExample                         : N1qlMetrics: N1qlMetrics{resultCount=10, errorCount=0, warningCount=0, mutationCount=0, sortCount=0, resultSize=970, elapsedTime='6.9993ms', executionTime='6.9993ms'}
2018-05-23 11:05:13.988  INFO   --- [           main] NonSpringExample                         : ********** END TIME: 1527053713988
2018-05-23 11:05:13.988  INFO   --- [           main] NonSpringExample                         : ********** Time taken: 196
2018-05-23 11:05:13.990  INFO   --- [           main] NonSpringExample                         : [{"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_100"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10001"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10002"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10003"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10004"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10005"}}]
2018-05-23 11:05:14.023 DEBUG   --- [-computations-3] c.couchbase.client.core.RequestHandler   : Got notified of a new configuration arriving.
2018-05-23 11:05:14.023 DEBUG   --- [-computations-3] c.couchbase.client.core.RequestHandler   : Starting reconfiguration.
2018-05-23 11:05:14.023 DEBUG   --- [-computations-3] c.couchbase.client.core.RequestHandler   : No open bucket found in config, disconnecting all nodes.

Java SDK Version:

       <dependency>
		<groupId>com.couchbase.client</groupId>
		<artifactId>java-client</artifactId>
		<version>2.5.8</version>
       </dependency>

I will share the RTO logs also in some time.

daschl · May 23, 2018, 6:30am

@himanshu.mps can you try this in a loop and check if it gets faster? If you execute just one query then yoiu might be running into a cold JVM which hasn’t done any JITing yet!

himanshu.mps · May 23, 2018, 6:37am

@daschl

Please ignore this comment. The comment has been updated in the coversation below.

I ran it in a loop of 10 and here are the results.

2018-05-23 12:05:44.855  INFO   --- [      cb-io-1-1] com.couchbase.client.core.node.Node      : Connected to Node 127.0.0.1/127.0.0.1
2018-05-23 12:05:45.416  INFO   --- [-computations-3] c.c.c.core.config.ConfigurationProvider  : Opened bucket pmc
2018-05-23 12:05:55.734  INFO   --- [           main] NonSpringExample                         : ********** START TIME: 1527057355732
2018-05-23 12:05:55.851  INFO   --- [-computations-1] NonSpringExample                         : N1qlMetrics: N1qlMetrics{resultCount=10, errorCount=0, warningCount=0, mutationCount=0, sortCount=0, resultSize=970, elapsedTime='7.0057ms', executionTime='7.0057ms'}
2018-05-23 12:05:55.863  INFO   --- [           main] NonSpringExample                         : ********** END TIME: 1527057355863
2018-05-23 12:05:55.887  INFO   --- [           main] NonSpringExample                         : ********** Time taken: 131
2018-05-23 12:05:55.894  INFO   --- [           main] NonSpringExample                         : [{"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_100"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10001"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10002"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10003"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10004"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10005"}}]
2018-05-23 12:05:55.909  INFO   --- [           main] NonSpringExample                         : ********** START TIME: 1527057355732
2018-05-23 12:05:55.929  INFO   --- [-computations-2] NonSpringExample                         : N1qlMetrics: N1qlMetrics{resultCount=10, errorCount=0, warningCount=0, mutationCount=0, sortCount=0, resultSize=970, elapsedTime='3.9996ms', executionTime='3.9996ms'}
2018-05-23 12:05:55.936  INFO   --- [           main] NonSpringExample                         : ********** END TIME: 1527057355936
2018-05-23 12:05:55.936  INFO   --- [           main] NonSpringExample                         : ********** Time taken: 204
2018-05-23 12:05:55.945  INFO   --- [           main] NonSpringExample                         : [{"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_100"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10001"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10002"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10003"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10004"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10005"}}]
2018-05-23 12:05:55.945  INFO   --- [           main] NonSpringExample                         : ********** START TIME: 1527057355732
2018-05-23 12:05:55.967  INFO   --- [-computations-3] NonSpringExample                         : N1qlMetrics: N1qlMetrics{resultCount=10, errorCount=0, warningCount=0, mutationCount=0, sortCount=0, resultSize=970, elapsedTime='4.9934ms', executionTime='4.9934ms'}
2018-05-23 12:05:55.976  INFO   --- [           main] NonSpringExample                         : ********** END TIME: 1527057355976
2018-05-23 12:05:55.991  INFO   --- [           main] NonSpringExample                         : ********** Time taken: 244
2018-05-23 12:05:55.992  INFO   --- [           main] NonSpringExample                         : [{"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_100"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10001"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10002"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10003"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10004"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10005"}}]
2018-05-23 12:05:55.994  INFO   --- [           main] NonSpringExample                         : ********** START TIME: 1527057355732
2018-05-23 12:05:56.039  INFO   --- [-computations-1] NonSpringExample                         : N1qlMetrics: N1qlMetrics{resultCount=10, errorCount=0, warningCount=0, mutationCount=0, sortCount=0, resultSize=970, elapsedTime='16.9999ms', executionTime='16.9999ms'}
2018-05-23 12:05:56.041  INFO   --- [           main] NonSpringExample                         : ********** END TIME: 1527057356041
2018-05-23 12:05:56.042  INFO   --- [           main] NonSpringExample                         : ********** Time taken: 309
2018-05-23 12:05:56.043  INFO   --- [           main] NonSpringExample                         : [{"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_100"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10001"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10002"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10003"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10004"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10005"}}]
2018-05-23 12:05:56.043  INFO   --- [           main] NonSpringExample                         : ********** START TIME: 1527057355732
2018-05-23 12:05:56.202  INFO   --- [-computations-2] NonSpringExample                         : N1qlMetrics: N1qlMetrics{resultCount=10, errorCount=0, warningCount=0, mutationCount=0, sortCount=0, resultSize=970, elapsedTime='50.0053ms', executionTime='50.0053ms'}
2018-05-23 12:05:56.207  INFO   --- [           main] NonSpringExample                         : ********** END TIME: 1527057356207
2018-05-23 12:05:56.208  INFO   --- [           main] NonSpringExample                         : ********** Time taken: 475
2018-05-23 12:05:56.215  INFO   --- [           main] NonSpringExample                         : [{"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_100"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10001"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10002"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10003"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10004"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10005"}}]
2018-05-23 12:05:56.216  INFO   --- [           main] NonSpringExample                         : ********** START TIME: 1527057355732
2018-05-23 12:05:56.282  INFO   --- [-computations-3] NonSpringExample                         : N1qlMetrics: N1qlMetrics{resultCount=10, errorCount=0, warningCount=0, mutationCount=0, sortCount=0, resultSize=970, elapsedTime='36.0037ms', executionTime='36.0037ms'}
2018-05-23 12:05:56.289  INFO   --- [           main] NonSpringExample                         : ********** END TIME: 1527057356289
2018-05-23 12:05:56.290  INFO   --- [           main] NonSpringExample                         : ********** Time taken: 557
2018-05-23 12:05:56.293  INFO   --- [           main] NonSpringExample                         : [{"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_100"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10001"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10002"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10003"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10004"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10005"}}]
2018-05-23 12:05:56.295  INFO   --- [           main] NonSpringExample                         : ********** START TIME: 1527057355732
2018-05-23 12:05:56.344  INFO   --- [-computations-1] NonSpringExample                         : N1qlMetrics: N1qlMetrics{resultCount=10, errorCount=0, warningCount=0, mutationCount=0, sortCount=0, resultSize=970, elapsedTime='16.0012ms', executionTime='16.0012ms'}
2018-05-23 12:05:56.351  INFO   --- [           main] NonSpringExample                         : ********** END TIME: 1527057356351
2018-05-23 12:05:56.351  INFO   --- [           main] NonSpringExample                         : ********** Time taken: 619
2018-05-23 12:05:56.352  INFO   --- [           main] NonSpringExample                         : [{"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_100"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10001"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10002"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10003"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10004"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10005"}}]
2018-05-23 12:05:56.352  INFO   --- [           main] NonSpringExample                         : ********** START TIME: 1527057355732
2018-05-23 12:05:56.395  INFO   --- [-computations-2] NonSpringExample                         : N1qlMetrics: N1qlMetrics{resultCount=10, errorCount=0, warningCount=0, mutationCount=0, sortCount=0, resultSize=970, elapsedTime='8.0011ms', executionTime='8.0011ms'}
2018-05-23 12:05:56.408  INFO   --- [           main] NonSpringExample                         : ********** END TIME: 1527057356408
2018-05-23 12:05:56.409  INFO   --- [           main] NonSpringExample                         : ********** Time taken: 676
2018-05-23 12:05:56.413  INFO   --- [           main] NonSpringExample                         : [{"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_100"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10001"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10002"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10003"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10004"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10005"}}]
2018-05-23 12:05:56.413  INFO   --- [           main] NonSpringExample                         : ********** START TIME: 1527057355732
2018-05-23 12:05:56.456  INFO   --- [-computations-3] NonSpringExample                         : N1qlMetrics: N1qlMetrics{resultCount=10, errorCount=0, warningCount=0, mutationCount=0, sortCount=0, resultSize=970, elapsedTime='7.499ms', executionTime='7.499ms'}
2018-05-23 12:05:56.459  INFO   --- [           main] NonSpringExample                         : ********** END TIME: 1527057356459
2018-05-23 12:05:56.462  INFO   --- [           main] NonSpringExample                         : ********** Time taken: 727
2018-05-23 12:05:56.465  INFO   --- [           main] NonSpringExample                         : [{"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_100"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10001"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10002"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10003"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10004"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10005"}}]
2018-05-23 12:05:56.478  INFO   --- [           main] NonSpringExample                         : ********** START TIME: 1527057355732
2018-05-23 12:05:56.510  INFO   --- [-computations-1] NonSpringExample                         : N1qlMetrics: N1qlMetrics{resultCount=10, errorCount=0, warningCount=0, mutationCount=0, sortCount=0, resultSize=970, elapsedTime='11.5009ms', executionTime='11.5009ms'}
2018-05-23 12:05:56.513  INFO   --- [           main] NonSpringExample                         : ********** END TIME: 1527057356513
2018-05-23 12:05:56.514  INFO   --- [           main] NonSpringExample                         : ********** Time taken: 781
2018-05-23 12:05:56.516  INFO   --- [           main] NonSpringExample                         : [{"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_100"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10001"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10002"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10003"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10004"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10005"}}]

himanshu.mps · May 23, 2018, 7:11am

@daschl @pvarley
Also I am not able to download core-io-1.6.0-dp1.jar from couchbase maven site

Caused by: org.apache.maven.wagon.authorization.AuthorizationException: Access denied to: http://files.couchbase.com/maven2/com/couchbase/client/core-io/1.6.0-dp1/core-io-1.6.0-dp1.jar , ReasonPhrase:Forbidden.

himanshu.mps · May 24, 2018, 4:32am

I did run it in a loop of 10…Previously I made a mistake of putting the startTime outside of the loop and that’s the reason it was giving incorrect results.

Here is the output and time looks ok now …

********** START TIME: 1527136210231
N1qlMetrics: N1qlMetrics{resultCount=10, errorCount=0, warningCount=0, mutationCount=0, sortCount=0, resultSize=970, elapsedTime='280.0137ms', executionTime='276.0142ms'}
********** END TIME: 1527136210832
********** Time taken: 601
[{"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_100"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10001"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10002"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10003"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10004"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10005"}}]
********** START TIME: 1527136210835
N1qlMetrics: N1qlMetrics{resultCount=10, errorCount=0, warningCount=0, mutationCount=0, sortCount=0, resultSize=970, elapsedTime='10.0006ms', executionTime='10.0006ms'}
********** END TIME: 1527136210856
********** Time taken: 21
[{"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_100"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10001"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10002"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10003"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10004"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10005"}}]
********** START TIME: 1527136210856
N1qlMetrics: N1qlMetrics{resultCount=10, errorCount=0, warningCount=0, mutationCount=0, sortCount=0, resultSize=970, elapsedTime='6.9989ms', executionTime='6.9989ms'}
********** END TIME: 1527136210873
********** Time taken: 17
[{"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_100"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10001"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10002"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10003"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10004"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10005"}}]
********** START TIME: 1527136210874
N1qlMetrics: N1qlMetrics{resultCount=10, errorCount=0, warningCount=0, mutationCount=0, sortCount=0, resultSize=970, elapsedTime='5.9986ms', executionTime='5.9986ms'}
********** END TIME: 1527136210889
********** Time taken: 15
[{"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_100"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10001"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10002"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10003"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10004"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10005"}}]
********** START TIME: 1527136210891
N1qlMetrics: N1qlMetrics{resultCount=10, errorCount=0, warningCount=0, mutationCount=0, sortCount=0, resultSize=970, elapsedTime='5.9932ms', executionTime='5.9932ms'}
********** END TIME: 1527136210905
********** Time taken: 14
[{"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_100"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10001"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10002"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10003"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10004"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10005"}}]
********** START TIME: 1527136210906
N1qlMetrics: N1qlMetrics{resultCount=10, errorCount=0, warningCount=0, mutationCount=0, sortCount=0, resultSize=970, elapsedTime='4.9993ms', executionTime='4.9993ms'}
********** END TIME: 1527136210923
********** Time taken: 17
[{"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_100"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10001"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10002"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10003"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10004"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10005"}}]
********** START TIME: 1527136210925
N1qlMetrics: N1qlMetrics{resultCount=10, errorCount=0, warningCount=0, mutationCount=0, sortCount=0, resultSize=970, elapsedTime='5.9986ms', executionTime='5.9986ms'}
********** END TIME: 1527136210952
********** Time taken: 27
[{"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_100"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10001"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10002"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10003"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10004"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10005"}}]
********** START TIME: 1527136210953
N1qlMetrics: N1qlMetrics{resultCount=10, errorCount=0, warningCount=0, mutationCount=0, sortCount=0, resultSize=970, elapsedTime='9.9987ms', executionTime='9.9987ms'}
********** END TIME: 1527136210972
********** Time taken: 19
[{"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_100"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10001"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10002"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10003"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10004"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10005"}}]
********** START TIME: 1527136210974
N1qlMetrics: N1qlMetrics{resultCount=10, errorCount=0, warningCount=0, mutationCount=0, sortCount=0, resultSize=970, elapsedTime='4.9998ms', executionTime='4.9998ms'}
********** END TIME: 1527136210989
********** Time taken: 15
[{"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_100"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10001"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10002"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10003"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10004"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10005"}}]
********** START TIME: 1527136210990
N1qlMetrics: N1qlMetrics{resultCount=10, errorCount=0, warningCount=0, mutationCount=0, sortCount=0, resultSize=970, elapsedTime='6.0001ms', executionTime='6.0001ms'}
********** END TIME: 1527136211005
********** Time taken: 15
[{"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_100"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_1000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10000"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10001"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10002"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10003"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10004"}}, {"pmc":{"javaClass":"com.test.gpc.api.vo.Product","glbl_holder_prod_id":"glblHolderProdId_10005"}}]

himanshu.mps · May 24, 2018, 6:24am

Sometimes some of the request take long…If I am running it in a loop, sometimes I see some of them taking time (see the one with 5080 milliseconds). What could be causing this issue ?

********** Sync Time taken: 65
********** Sync Time taken: 77
********** Sync Time taken: 67
********** Time taken: 56
********** Time taken: 102
********** Time taken: 98
********** Time taken: 64
********** Time taken: 55
********** Time taken: 81
********** Time taken: 101
********** Time taken: 5080
********** Time taken: 64
********** Time taken: 71
********** Time taken: 102
********** Time taken: 66
********** Time taken: 65
********** Time taken: 68
********** Time taken: 99
********** Time taken: 100
********** Time taken: 59
********** Time taken: 61

ingenthr · April 26, 2022, 12:29am

It could be time queued for the query service to handle the request or time in the client queued to be sent.