Query slow in a bucket which is having only 800 records

SQL++
1

Hi,

I’m using couchbase server 5.1 running on Centos 7. There are some buckets on this db server:
image

On “News” bucket, there is only 800 records and a cover index already created:

CREATE INDEX news_type_cate_all2_idx ON News(newsType,cate,dateTimeCreated,alias,content) WHERE (type = “News”)

But this query still take 600ms to 1500ms to run:

select content, alias, cate,dateTimeCreated from News where type = 'News'  and newsType='news' and cate='thi-truong' order by dateTimeCreated desc limit 15 offset 0

The loading of machine, I checked also got no problem, CPU is very free :

image
image922×373 10.9 KB

I have another development server, which is having only “News” bucket and running this cmd is fast, only took 200ms.

This is exec plan on problem server:

{
“#operator”: “Sequence”,
“#stats”: {
“#phaseSwitches”: 2,
“execTime”: “2.12µs”,
“kernTime”: “1.542978677s”
},
“~children”: [
{
“#operator”: “Authorize”,
“#stats”: {
“#phaseSwitches”: 4,
“execTime”: “5.471µs”,
“kernTime”: “1.541809468s”,
“servTime”: “1.13152ms”
},
“privileges”: {
“List”: [
{
“Target”: “default:News”,
“Priv”: 7
}
]
},
“~child”: {
“#operator”: “Sequence”,
“#stats”: {
“#phaseSwitches”: 3,
“execTime”: “3.611µs”,
“kernTime”: “1.541794638s”
},
“~children”: [
{
“#operator”: “Sequence”,
“#stats”: {
“#phaseSwitches”: 2,
“execTime”: “1.678µs”,
“kernTime”: “1.541553633s”
},
“~children”: [
{
“#operator”: “IndexScan2”,
“#stats”: {
“#itemsOut”: 430,
“#phaseSwitches”: 1723,
“execTime”: “3.213124ms”,
“kernTime”: “1.348019ms”,
“servTime”: “1.536882351s”
},
“covers”: [
“cover ((News.newsType))”,
“cover ((News.cate))”,
“cover ((News.dateTimeCreated))”,
“cover ((News.alias))”,
“cover ((News.content))”,
“cover ((meta(News).id))”
],
“filter_covers”: {
“cover ((News.type))”: “News”
},
“index”: “news_type_cate_all2_idx”,
“index_id”: “f150c54a5cd26f7a”,
“index_projection”: {
“entry_keys”: [
0,
1,
2,
3,
4
]
},
“keyspace”: “News”,
“namespace”: “default”,
“spans”: [
{
“exact”: true,
“range”: [
{
“high”: “"news"”,
“inclusion”: 3,
“low”: “"news"”
},
{
“high”: “"thi-truong"”,
“inclusion”: 3,
“low”: “"thi-truong"”
}
]
}
],
“using”: “gsi”,
“#time_normal”: “00:01.5400”,
“#time_absolute”: 1.540095475
},
{
“#operator”: “Sequence”,
“#stats”: {
“#phaseSwitches”: 5,
“execTime”: “3.427µs”,
“kernTime”: “1.541525587s”
},
“~children”: [
{
“#operator”: “Filter”,
“#stats”: {
“#itemsIn”: 430,
“#itemsOut”: 430,
“#phaseSwitches”: 1725,
“execTime”: “1.700648ms”,
“kernTime”: “1.539774465s”
},
“condition”: “(((cover ((News.type)) = "News") and (cover ((News.newsType)) = "news")) and (cover ((News.cate)) = "thi-truong"))”,
“#time_normal”: “00:00.0017”,
“#time_absolute”: 0.001700648
},
{
“#operator”: “InitialProject”,
“#stats”: {
“#itemsIn”: 430,
“#itemsOut”: 430,
“#phaseSwitches”: 1727,
“execTime”: “1.69514ms”,
“kernTime”: “1.539812941s”
},
“result_terms”: [
{
“expr”: “cover ((News.content))”
},
{
“expr”: “cover ((News.alias))”
},
{
“expr”: “cover ((News.cate))”
},
{
“expr”: “cover ((News.dateTimeCreated))”
}
],
“#time_normal”: “00:00.0016”,
“#time_absolute”: 0.0016951400000000001
}
],
“#time_normal”: “00:00.0000”,
“#time_absolute”: 0.000003427
}
],
“#time_normal”: “00:00.0000”,
“#time_absolute”: 0.0000016779999999999999
},
{
“#operator”: “Order”,
“#stats”: {
“#itemsIn”: 430,
“#itemsOut”: 15,
“#phaseSwitches”: 895,
“execTime”: “1.672247ms”,
“kernTime”: “1.539968818s”
},
“limit”: “15”,
“sort_terms”: [
{
“desc”: true,
“expr”: “cover ((News.dateTimeCreated))”
}
],
“#time_normal”: “00:00.0016”,
“#time_absolute”: 0.001672247
},
{
“#operator”: “Limit”,
“#stats”: {
“#itemsIn”: 15,
“#itemsOut”: 15,
“#phaseSwitches”: 65,
“execTime”: “10.28µs”,
“kernTime”: “1.541671615s”
},
“expr”: “15”,
“#time_normal”: “00:00.0000”,
“#time_absolute”: 0.00001028
},
{
“#operator”: “FinalProject”,
“#stats”: {
“#itemsIn”: 15,
“#itemsOut”: 15,
“#phaseSwitches”: 67,
“execTime”: “16.176µs”,
“kernTime”: “1.54175627s”
},
“#time_normal”: “00:00.0000”,
“#time_absolute”: 0.000016176
}
],
“#time_normal”: “00:00.0000”,
“#time_absolute”: 0.0000036110000000000002
},
“#time_normal”: “00:00.0011”,
“#time_absolute”: 0.001136991
},
{
“#operator”: “Stream”,
“#stats”: {
“#itemsIn”: 15,
“#itemsOut”: 15,
“#phaseSwitches”: 37,
“execTime”: “4.952µs”,
“kernTime”: “1.542964694s”
},
“#time_normal”: “00:00.0000”,
“#time_absolute”: 0.000004952
}
],
“~versions”: [
“2.0.0-N1QL”,
“5.1.1-5723-enterprise”
],
“#time_normal”: “00:00.0000”,
“#time_absolute”: 0.00000212
}

2 
{
“#operator”: “IndexScan2”,
“#stats”: {
“#itemsOut”: 430,
“#phaseSwitches”: 1723,
“execTime”: “3.213124ms”,
“kernTime”: “1.348019ms”,
“servTime”: “1.536882351s”
}

From above information IndexScan2 servTime is high (Check Information provided section of Optimize N1QL performance using request profiling - The Couchbase Blog)
IndexScan took the time, you may have to increase the indexer memory. cc @deepkaran.salooja

As you are doing order by dateTimeCreated desc. Create index with dateTimeCreated DESC

CREATE INDEX news_type_cate_all2_idx ON News(newsType,cate,dateTimeCreated DESC,alias,content) WHERE (type = “News”)

3

@tinygipxy, you may need to size it properly based on how many indexes(and indexed data) you have. If resident ratio is too low, scans will be slow. Increasing the memory quota should help.

4

This is my ratio of News bucket, it’s always 100%:

image
image.png1207×375 28.4 KB

5

This is the result after create index by DESC:
1. Select all (slow):

image
image.png1102×438 57.3 KB

2. Select index cover columns (very fast):

image
image.png981×427 48.8 KB

6

Fetch more data:

image
image.png903×424 47.4 KB

7

My concern here is that we only 800 records on that News bucket, why fetching time for only 1 record (limit 1) took so much of time like that ?

8

In (1) it is using different index news_type_cate_idx, drop this and try it.
The 100% resident is bucket data not index data. increase memory quota in Settings—>Index

You are using ORDER BY it needs to get all qualified documents sort and produce 1.
If you remove ORDER BY it will be fast for 1 record.
Please check out image it tells each box in/out items

Check this link how to analyze performance issues https://blog.couchbase.com/optimize-n1ql-performance-using-request-profiling/

Also if you allocated 500MB indexer and you have many indexes, concurrent scans needs manage with in that memory (index pages may have to read from disk). As Deep suggested you need to do proper sizing.

9

Checkout Designing Index For Query In Couchbase N1QL in https://blog.couchbase.com/wp-content/uploads/2017/10/N1QL-A-Practical-Guide-2nd-Edition.pdf

10

I allocated 50GB RAM for index, and still free alot:

image
image.png916×249 24.2 KB

11

These are Data node info.

You need to look into

Settings —>Service Memory Quotas

Also Look into
Buckets -->Statistics–>Index Stats:

Example:

55%20AM
Screen Shot 2018-07-14 at 8.01.55 AM.png1586×838 47 KB

12

In my screen, u can see, it’s still free 24GB ram for index ( I allocated 50GB). Just now I restarted Couchbase server and the query time become 200ms. I think sometime need restart Couchbase server. Thank you

13

A couple of leaks were fixed as part of 5.1.1 release (MB-29194 and MB-29197). If you are using 5.1.0, it would be good to upgrade to 5.1.1 and see if you observe a better behavior.