Advanced SQL++ (N1QL) Troubleshooting

Introduction

This article will cover some common issues that can be encountered when working with SQL++

• Panics and assert fails
• Hangs and unresponsive nodes
• OOMs and large memory consumption
• Slow requests
• Generalized poor node performance
• Wrong results
• Inconsistent results
• Different behavior between nodes

We will review the possible causes for these issues, how to confirm if you're seeing one of those, and what diagnostic information should be collected to investigate the issue.

Usually, it is not an easy task to determine the type of an issue. For example, a panic message could be not related to Couchbase directly, or be a symptom of a race condition in concurrent processes. Slow-running requests and overall poor performance could be caused by an unoptimized query or index, by not optimal query’s execution plan, or even because the node is overloaded by other collocated services. Also, SQL++ relies on other Couchbase internal services and clients, so the issue is not always related to SQL++ solely. Even if we can determine the type of the issue, different types of issues require different diagnostic approaches and different diagnostic data to be collected.

Runtime errors, Panics, and Assert failures

• Low-level issues, like invalid memory access or accessing a locked mutex.
• High-level issues, like the execution of an operator in an incorrect state.
• Specific cases, like concurrent access to the Cluster map
• Out-of-memory situations

SELECT *, meta().plan FROM system:completed_requests ORDER BY requestTime DESC LIMIT 1000 
//Note, that ORDER BY requestTime DESC LIMIT 1000 is optional; 
//ORDER BY requestTime - orders the completed requests by time; 
//LIMIT 1000 - outputs the first 1000 records

_time=2020-10-29T15:22:45.903-07:00 _level=SEVERE _msg=stack: goroutine 2231 [running]:
github.com/couchbase/query/execution.(*Context).Recover(0xc002512240, 0x0)
        /home/couchbase/jenkins/workspace/couchbase-server-unix/goproj/src/github.com/couchbase/query/execution/context.go:879 +0xbb
panic(0x21ac240, 0x382a620)
        /home/couchbase/.cbdepscache/exploded/x86_64/go-1.13.7/go/src/runtime/panic.go:679 +0x1b2
github.com/couchbase/query/datastore/couchbase.(*namespace).Objects(0xc00075c900, 0x248b30a, 0x7, 0x2765fe0, 0xc00075c900, 0x0)
       /home/couchbase/jenkins/workspace/couchbase-server-unix/goproj/src/github.com/couchbase/query/datastore/couchbase/couchbase.go:796 +0x1e5
github.com/couchbase/query/datastore/system.(*keyspaceIndex).ScanEntries(0xc00031e5d0, 0xc0002cf8f0, 0x24, 0x7fffffffffffffff, 0x248ebc2, 0x9, 0x2717800, 0x3a728c0, 0xc00250b320)
/home/couchbase/jenkins/workspace/couchbase-server-unix/goproj/src/github.com/couchbase/query/datastore/system/system_keyspace_keyspaces.go:474 +0x1c3
github.com/couchbase/query/execution.(*PrimaryScan).scanEntries(0xc002580b40, 0xc002512240, 0xc00250b320, 0x7fffffffffffffff)
        /home/couchbase/jenkins/workspace/couchbase-server-unix/goproj/src/github.com/couchbase/query/execution/scan_primary.go:203 +0x1b6
created by github.com/couchbase/query/execution.(*PrimaryScan).scanPrimary
        /home/couchbase/jenkins/workspace/couchbase-server-unix/goproj/src/github.com/couchbase/query/execution/scan_primary.go:94 +0x225

2023-09-27T08:48:37.002-05:00 [SEVERE] stack: goroutine 357156611 [running]:
github.com/couchbase/query/execution.(*Context).Recover(0xc000149080, 0xc000177180)
/home/couchbase/jenkins/workspace/couchbase-server-unix/goproj/src/github.com/couchbase/query/execution/context.go:1206 +0x8a
panic({0x23f1b80, 0x3f8cb10})
/home/couchbase/.cbdepscache/exploded/x86_64/go-1.18.7/go/src/runtime/panic.go:838 +0x207
github.com/couchbase/query/execution.(*base).runConsumer.func1.2()
/home/couchbase/jenkins/workspace/couchbase-server-unix/goproj/src/github.com/couchbase/query/execution/base.go:895 +0xb6
panic({0x23f1b80, 0x3f8cb10})

• Stack trace message for failing goroutine thread, as in the examples above
• CPU profile, Memory profile, and GoRoutine for the Query Service (find commands below this list)
• The SQL++ query statement that fails
• If the query runs through a Couchbase SDK, the SDK logs
• Couchbase Cluster logs
• Optionally, the test case showing the issue

curl u <USERNAME>:<PASSWORD> -s http://localhost:8093/debug/pprof/heap > $(hostname)-cbq-hprof.mprof

curl -u <USERNAME>:<PASSWORD> -s http://localhost:8093/debug/pprof/profile?seconds=60 > $(hostname)-cpu.pprof

curl u <USERNAME>:<PASSWORD> -s http://localhost:8093/debug/pprof/goroutine?debug=1 > $(hostname)-goroutine.log

Hanged and stuck queries

Requests that don't complete at the first run but complete at the next one, statements that never complete at all, as well as queries that don't complete because of the unresponsive node fall under this category.

To investigate these, first, you need to evaluate the situation and ensure that the issue is with a query, and not with a stuck Application/SDK, slow processing, or overall cluster issues. To ensure that the query is stuck and not just slow we need to collect system:completed_requests twice. Note, that system:completed_requests are collected in logs of Couchbase version 7 and higher automatically, while in versions 6.X you will have to query it manually(refer to archived documentation for more details about versions 6.X). Then it would help if you compared the time spans of operation phases. If they are increased it means the query is slow running and not stuck. If queries are just slow and not stuck, it may be happening due to insufficient resources of the Cluster that is running the queries.

What needs to be collected for troubleshooting:

• CPU profile, Memory profile, and GoRoutine for the Query Service (find commands below the list)
• The SQL++ query statement that stuck
• If the query runs by means of a Couchbase SDK, the SDK logs
• Couchbase Cluster logs
• Optionally, the test case showing the issue

Commands for collecting CPU profile, Memory profile, and GoRoutine for the Query Service. Please, run the following commands from the relevant query node(s) at the time of the issue, and verify the profiles were successfully collected (ensure the files are not empty). If it's possible collect two sets of profiles with a few seconds time difference between collections:

Query Engine Memory (Heap) Profile:

curl -u <USERNAME>:<PASSWORD> -s http://localhost:8093/debug/pprof/heap > $(hostname)-cbq-hprof.mprof

Query Engine CPU Profile:

curl -u <USERNAME>:<PASSWORD> -s http://localhost:8093/debug/pprof/profile?seconds=60 > $(hostname)-cpu.pprof

Query Engine GoRoutine:

curl -u <USERNAME>:<PASSWORD> -s http://localhost:8093/debug/pprof/goroutine?debug=1 > $(hostname)-goroutine.log

How to verify if the node is stuck, not the query:

You can verify if the issue is node-wide by running a simple SQL++ query by executing a REST API request:

curl http://<ip of failing node>:8093/query/service -u Administrator:password -d 'statement=select 1' 
//'statement=select 1' is an example of a simple unambiguous request

If you get no response, collect the active requests from the /admin/active_requests endpoint. Try to run your query in a while, to ensure the issue is reproducible.

Out-of-memory leaks

Query service doesn't have a direct quota that can be assigned to it. It means, that the Query service can occupy all available memory on the node. That may lead to Out-of-memory situation. When such situation occurs, OS kernel kills the Query service(cbq-engine process) because a process that tries to use more memory can't extend the memory heap at the moment of issue(it's not always the Query service itself).

Note, that the memory can't be occupied after Query service was killed by the OS. It happens because Golang garbage collector needs time to free the memory. Golang allocates memory in OS in blocks called memory pages. And garbage collector must free up the whole page until it becomes available to Golang. If the memory is highly fragmented it may take a while. Golang runtimes wait 5 minutes monitoring memory usage before deciding to relinquish memory pages.

What needs to be collected for troubleshooting:

• Memory profile, and GoRoutine for the Query Service (find commands below the list)
• Couchbase Cluster logs
• Optionally, the test case showing the issue

Commands for collecting Memory profile, and GoRoutine for the Query Service. Please, run the following commands from the relevant query node(s) at the time of the issue, and verify the profiles were successfully collected (ensure the files are not empty). If it's possible collect two sets of profiles, first at the moment of the issue, second when the memory usage grows:

Query Engine Memory (Heap) Profile:

curl u <USERNAME>:<PASSWORD> -s http://localhost:8093/debug/pprof/heap > $(hostname)-cbq-hprof.mprof

Query Engine GoRoutine:

curl u <USERNAME>:<PASSWORD> -s http://localhost:8093/debug/pprof/goroutine?debug=2 > $(hostname)-goroutine.log

Performance

Performance of SQL++ queries is a broad topic to discuss. To fully understand it we highly encourage you to go over our documentation on Query: Fundamentals, Using Indexes, and SQL++ Language Reference. Couchbase has Cost-Based Optimizer included in the Query service, however, it is the users' responsibility to optimize an SQL++ query, and use the optimal index for the query. Go over Indexing and Query Performance article for more details on possible optimizations.

Besides our official documentation, we also have a few great articles on our blog:

• Optimize N1QL performance using request profiling (it relates to an old version of Couchbase Server, but covers the query profiling information that is used for troubleshooting)
• N1QL Index Advisor: Improve Query Performance, Productivity
• Boost Query Efficiency with Cost-Based Optimization in Couchbase

Ways to increase the performance of the Query service heavily depend on monitoring and profiling information. Couchbase Server supports Multi-Dimentional Scaling for ease of adding resources to clusters and separate nodes.

Overloaded nodes

If you determined that your Query nodes suffer overall slowness, you will need to collect the below to investigate the issue and take measures:
- First, set Completed Threshold to 0. It ensures that all queries run on nodes will be logged. The completed Threshold is the completed query duration (in milliseconds) beyond which the query is logged in the completed requests catalog.
- Collect system:completed_requests
- Collect cluster logs, it will contain CPU and Memory (Heap) profiles if you use Couchbase Server 7 or higher, which are useful for diagnostic purposes.

Please collect Cluster logs at the time the issue is occurring.

Slow requests

Slow requests can be investigated by going over the query profilings of the problematic query. You may find next symptoms:

• High kernel time (kernTime) means that the query phase spent most of the phase time waiting for the kernel to schedule the execution time for the phase. Most probably, your bottleneck is downstream.
• High service time (servTime) means that most of the time was spent waiting for another service, such as index or data.
• High Scan phase #itemsOut count means that the index used by the query is unoptimized and returns a lot of items. However, sometimes the query should return a lot of items, this should be evaluated depending on each separate query
• High filter phase #itemsIn and, at the same time, low #itemsOut means that the index used by the query is unoptimized.
• High Stream execution time (execTime) means the documents processed are large, or the Query service experiences resource pressure.
• Unexpectedly high execution time for an #operator means that the bottleneck is the #operator phase itself(for example: "#operator": "Authorize", #operator": "Sequence, etc.)

Note, that the service time (servTime) is not the time spent on the Query service solely. It also includes all the time spans spent outside the SQL++ code execution, e.g. Index client, Full-Text Search client, Data service, etc. It is highly recommended to investigate CPU profiles and Goroutines when you encounter high service time in any phase of SQL++ query.

Poor query execution plan

Each time a query is executed, an EXPLAIN command is automatically run in the background to retrieve the query plan for that query. Find more details on how to review the query plan in our Query Plans documentation article. If you review such a plan and see that some phase is taking an abnormally long time, you may want to re-evaluate your indexes and the query itself.

• Is your index optimized?
• Can the query be written better?

Assisting with your design of bespoke index definition, or writing queries or client SDK code are best handled by our Solutions Architects as part of a Professional Services engagement. Contact us, and we will be more than happy to help you.

Query returns wrong results

The most often case of returning wrong results is when the query returns insufficient results. For example, you expect to see 10 documents, but only 5 returned. However, sometimes it could be wrong documents or no results at all. The first thing to check in such cases is whether your data is not corrupted. It could be disk damage, corruption of the File System, or any other reasons. You can verify if the documents are indeed present in your bucket using Web Console.

If your query output less than expected, we recommend going over the query request profiling information and searching for operators with fewer #itemsOut than expected or no #itemsOut at all. This operator usually will be the problematic one.

What needs to be collected for troubleshooting:

• Couchbase Cluster logs
• Optionally, the test case showing the issue

Inconsistent results

Last but not least, the query may return inconsistent results, some parts of the expected results may be missing intermittently, and it could contain old data or no data at all. The main symptom of inconsistent results is periodicity. In that case, make sure that the request isn't suffering because of one of the reasons we already discussed. It could be a timeout, a request being canceled, a connection closed, or even a service panic.

When all other possible reasons are excluded, you need to run your query with query profiling, and then execute the query until you obtain correct and inconsistent results. Investigate the profiling for both to see what are the differences. Usually, it will give you some clues on which operation or operation phase is working badly. Usually, inconsistent runs will have fewer #itemsOut

What needs to be collected for troubleshooting:

• Couchbase Cluster logs
• Request profiling for both correct and inconsistent runs