Completed Requests basics

Introduction

The Query Service maintains several catalogs to monitor various insights. You may want to review the Monitor Queries documentation to learn more about the different catalogs that exist within Query Service. One of the most important log catalogs is Completed Requests (may be referred to as system:completed_requests)

If you use Couchbase Server version prior to 7.0, you may be asked by Couchbase Support to upload a Completed Requests logs when you encounter issues with Query Service. If you use Couchbase Server version 7.0 and above - Completed Requests logs are collected automatically within all Couchbase logs.

In this article, we will review how to collect these Completed Requests logs and what each field in it means.

The system:completed_requests catalog contains information about all queries that took longer than the completed-threshold to complete - the default value for completed-threshold is 1000ms, meaning any queries which exceed this value will be included in the system:completed_requests catalogue. Also, you may want to specify completed-limit. The completed-limit field sets the number of most recent requests to be tracked in the system:completed_requests catalog. The default value is 4000. Specify 0 to not track any requests and -1 to set no limit.

Completed Requests can be useful for investigating your issues relating to N1QL query performance which are commonly received via Support Tickets, e.g. of the issue you may want to file with Couchbase Support: "N1QL query operations are timing out from our application" or "N1QL queries are executing slower than we expect".

You can collect the system:completed_requests output by running the following query on their cluster, which will return the system:completed_requests output in the query result:

SELECT *, meta().plan FROM system:completed_requests;

Another option would be to collect it using the Admin REST API:

curl -u Administrator:password http://localhost:8093/admin/completed_requests

Or you can execute the query of system:completed_requests via the command line using our cbq tool (command line shell for N1QL) which is located at /opt/couchbase/bin. Please ensure this is run from a Query Service node, replacing <USERNAME> and <PASSWORD> with the necessary credentials for your cluster:

/opt/couchbase/bin/cbq -u <USERNAME> -p <PASSWORD> -e "http://localhost:8091" --script="SELECT *, meta().plan FROM system:completed_requests;" > completed_requests.txt

The system:completed_requests catalog is stored per Query Service node but the catalogs for all nodes are collated when system:completed_request is queried for. This means that any system:completed_request output that you collect will be the same for all nodes, and will cover all Query Service nodes in the cluster.

Note that the system:completed_request catalog is only intended to be a cache - it is not persisted. This means that restarting a Query Service node will result in the loss of the cached completed requests. Similarly failing over/rebalancing a node out of the cluster will also result in the loss of the cached completed requests.

Example output

[
  {
    "completed_requests": {
      "elapsedTime": "2m19.849196595s",
      "errorCount": 0,
      "node": "query4.sandbox.org:8091",   
      "phaseCounts": { 
        "fetch": 572219,   
        "filter": 572219,  
        "indexScan": 616679
      },
      "phaseOperators": {
        "authorize": 1,
        "fetch": 1,
        "filter": 1,   
        "indexScan": 2 
      },
      "phaseTimes": {  
        "authorize": "585.969µs",
        "fetch": "16.63964079s",
        "filter": "17.852300911s",
        "indexScan": "3.546053043s",
        "instantiate": "38.584µs",
        "parse": "2.543202ms",
        "plan": "199.867924ms",
        "run": "2m19.646670554s"
      },
      "remoteAddr": "10.76.22.185:48674",  
      "requestId": "077e375e-516a-4398-8035-9e24e006260a", 
      "requestTime": "2022-06-09T17:31:13.549-05:00",  
      "resultCount": 572219,   
      "resultSize": 12456347792,   
      "scanConsistency": "unbounded",  
      "serviceTime": "2m19.849135075s",
      "state": "completed",
      "statement": "select *,meta().id from bucket1 where entityType = 1;",
      "useCBO": true,  
      "userAgent": "Go-http-client/1.1 (CBQ/2.0)",
      "users": "Administrator" 
    }
  }
]

 

Output Fields in Detail

ElapsedTime

"elapsedTime": "2m19.849196595s",

The total time taken for the N1QL query to complete.

 

ErrorCount

"errorCount": 0,

The number of errors encountered when executing the query.

As an example, if you try executing a query with a syntax error ( incorrectly spell LIMITT instead of LIMIT) (with completed-threshold set to 0), this will result in the errorCount being incremented, and the actual error will also be shown on the corresponding entry in the Completed Requests:

"errorCount": 1,
"errors": [
 {
  "code": 3000,
  "icause": "syntax error - at 10",
  "key": "parse.syntax_error",
  "message": ""
 }
],

Some further information can also be found in the N1QL Error Codes documentation.

 

Node

"node": "query4.sandbox.org:8091",

The IP address or hostname of the Query Service node that the query request was sent to.

For application clients (SDKs) and CBQ tool, queries are distributed between all Query Service nodes using a Round Robin algorithm (eg, if there are 4 Query Service nodes, 1->2->3->4->1->2…) to equally load balance queries across all Query Service nodes.

 

PhaseCounts

"phaseCounts": {
"fetch": 572219,
"filter": 572219,
"indexScan": 616679

This section represents the number of documents processed by various operators used in during the execution of the query plan, such as authorize, indexscan, fetch, parse, plan, run, etc.

The above log snippet indicates that a fetch operator was used for this query and that 572219 documents were fetched from the Data Service.

It indicates that 572219 documents were filtered with a filter operator after being retrieved from the Data Service.

Finally, it indicates that 616679 documents were returned from Index Scans (indexScan operator) from the Index Service.

An explanation of what phaseCounts represents can also be found in the Monitoring and Profiling documentation.

 

PhaseOperators

"phaseOperators": {
"authorize": 1,
"fetch": 1,
"filter": 1, 
"indexScan": 2 
},

This section denotes the number of each operator required for the query.

I.e. this query required 1 authorize operator, 1 fetch, and 2 indexScan operators.

This section is also described in the Monitoring and Profiling Details documentation.

 

PhaseTimes

"phaseTimes": { 
"authorize": "585.969µs",
"fetch": "16.63964079s",
"filter": "17.852300911s",
"indexScan": "3.546053043s",
"instantiate": "38.584µs",
"parse": "2.543202ms",
"plan": "199.867924ms",
"run": "2m19.646670554s"
},

The cumulative execution times for the operators involved in the execution of the query plan, such as authorize, indexScan, fetch, parse, plan, run, etc.

Note that run covers the execution of all Operators - the cumulative total.

This is also described in the Monitoring and Profiling Details documentation.

 

RemoteAddr

"remoteAddr": "10.76.22.185:48674",

The IP address of the client sending the request. E.g., this could be the IP address of an application client (SDK client), or the location where a request was executed via CBQ tool.

 

RequestId

"requestId": "077e375e-516a-4398-8035-9e24e006260a",

A unique identifier for the query request.

 

RequestTime

"requestTime": "2022-06-09T17:31:13.549-05:00",

The time the query request was executed on the Couchbase Server side.

 

Resultcount

"resultCount": 572219,

The total number of documents included in the final query result.

 

ResultSize

"resultSize": 12456347792,

The total size of the query results in Bytes.

 

ScanConsistency

"scanConsistency": "unbounded",

The Scan Consistency is used for Index scanning.

Indexes are eventually consistent with the Data Service. This means an Index Scan is able to return indexed data with low latency, but the data may not be the most update to date at a given time. This is because when a mutation is made to a document via the Data Service, the mutation must then be streamed to the Index Service via the Projector process in order for the index to be updated with the latest value. After a mutation is made to the document in the Data Service, the Index could be scanned before the new mutation has been propagated and updated in the Index, meaning the latest mutation may not always be included in the query result.

There are 4 user-definable settings for Index Scan consistency. The Scan Consistency documentation contains more information on each consistency level:

not_bounded (unbounded): No timestamp vector is used in the index scan. This is the fastest mode because it avoids the costs of obtaining the vector and waiting for the index to catch up to the vector.

at_plus (scan_plus): This implements bounded consistency. The request includes a scan_vector parameter and value, which is used as a lower bound. This can be used to implement read-your-own-writes (RYOW).

request_plus (scan_plus): This implements strong consistency per request. Before processing the request, a current vector is obtained. The vector is used as a lower bound for the statements in the request. If there are DML statements in the request, RYOW is also applied within the request. If request_plus is specified in a query that runs during a failover of an index node, the query waits until the rebalance operation completes and the index data has rebalanced before returning a result.

statement_plus: This implements strong consistency per statement. Before processing each statement, a current vector is obtained and used as a lower bound for that statement.

Note that at_plus and request_plus both maps to scan_plus as shown in the system:completed_requests scanConsistency field.

 

ServiceTime

"serviceTime": "2m19.849135075s",

Indicates the total time from when a servicer picks up the request to the end of execution. Service time can be different from the elapsedTime which indicates the total time for the request. E.g., the request could spend time sitting in the queue waiting to be picked up by a servicer - the service time only takes into account the time once it has been picked up by a servicer to completion.

 

State

"state": "completed",

Shows the status of a query. The query will go through various states during its execution:

 

submitted – The initial state once the Query Service has accepted the request and the request is waiting in a queue to be picked up by a servicer.

running – Query execution is in progress.

success – Query execution has been completed without errors. The state will then change to completed.

errors – Query execution has been completed with errors. The state will then change to completed.

completed – The request has been completed (either with or without errors).

stopped – The request was manually stopped by the user.

timeout – The request reached the timeout and stopped.

closed – The client (application) closed the request before Couchbase Server completed the request. (The client closed the port and the request was terminated).

fatal – A serious error occurred, the request must stop immediately. E.g., authorization failed, or the request has a syntax issue. Most likely this happens before returning any result.

aborted – the request caused a panic within the Query Service and stopped.

 

Completed Requests will only show one of the end states. The transient states that occur during execution are not captured in the Completed Requests. If the request is still executing, the request will appear in the system:active_requests catalog, which may show one of the transient states. The following are the end states: completed, stopped, timeout, closed, fatal, aborted

 

Statement

"statement": "select *,meta().id from bucket1 where entityType = 1;",

Shows the query statement that was executed.

 

UseCBO

"useCBO": true,

Indicates whether the Cost Based Optimiser (available in Couchbase Server version 7.0+) is enabled for the request. This can be configured at the cluster/node/request level.

 

UserAgent

"userAgent": "Go-http-client/1.1 (CBQ/2.0)",

The client the query request was submitted from, e.g., an application (SDK), Web UI, or CBQ.

For the Couchbase UI (Query Workbench) the value of this field will be similar to the following (dependent on the browser used):

"userAgent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 
(KHTML, like Gecko) Chrome/102.0.0.0 Safari/537.36 (Couchbase Query Workbench)",

If executed from an application client (SDK) - the version of the SDK will be specified above.

 

Users

"users": "Administrator"

The name of the User the query request was issued by.

 

Related Statistics

The Completed Requests output may also contain statistics such as the following:

"#stats": {
"#heartbeatYields": 1,
"#itemsOut": 130408,
"#phaseSwitches": 521635,
"execTime": "305.130177ms",
"kernTime": "24.852565406s",
"servTime": "79.006846ms"
}

 

These are explained further below.

heartbeatYields
This is a count of the number of times a producer (the operator sending the documents down the query pipeline) has stopped to allow the subsequent consumer (the operator receiving the documents) to run.

itemsIn
The number of items ingested for the query.

itemsOut
The number of items processed by the query.

phaseSwitches
The number of times the operator has changed its state (i.e. from waiting for data to waiting to be scheduled to executing operator code).

execTime
The time spent executing operator code.

kernTime
The time spent waiting to be scheduled for CPU time. A high kernTime typically either implies a bottleneck in an operator further down the pipeline or that the Query Service has many requests to process (so the scheduled waiting time for the CPU will be higher).

servTime
The time spent waiting for other services to supply the data.