None of N1QL Query complete

Rabzu · November 2, 2017, 10:48pm

CB version: 4.5.1
number of documents = 170
single node

Simplest Query:
SELECT * FROM pamain

Index
CREATE PRIMARY INDEX #primary ON pamain

Log from: /opt/couchbase/var/lib/couchbase/logs/query.log

2017-11-03T02:44:48.528+04:00 [Info] connected with 1 indexers
2017-11-03T02:44:48.528+04:00 [Info] index 1466350299188775374 has 1 replicas
2017-11-03T02:44:48.528+04:00 [Info] GSIC[default/pamain-1509634068408973674] logstats "pamain" {"gsi_scan_count":2327,"gsi_scan_duration":3834683307,"gsi_throttle_duration":930448,"gsi_prime_duration":3590226708,"gsi_blocked_duration":0,"gsi_totalbackfills":0}
2017-11-03T02:44:48.528+04:00 [Info] index 14822891103662477751 has 1 replicas
2017-11-03T02:44:48.528+04:00 [Info] client load stats {"14822891103662477751": 1.6967825544616883e+06,"1466350299188775374": 1.4706997550482107e+06}

2017-11-03T02:44:48.528+04:00 [Info] connected with 1 indexers
2017-11-03T02:44:48.528+04:00 [Info] index 1466350299188775374 has 1 replicas
2017-11-03T02:44:48.528+04:00 [Info] GSIC[default/pamain-1509634068408973674] logstats "pamain" {"gsi_scan_count":2327,"gsi_scan_duration":3834683307,"gsi_throttle_duration":930448,"gsi_prime_duration":3590226708,"gsi_blocked_duration":0,"gsi_totalbackfills":0}
2017-11-03T02:44:48.528+04:00 [Info] index 14822891103662477751 has 1 replicas
2017-11-03T02:44:48.528+04:00 [Info] client load stats {"14822891103662477751": 1.6967825544616883e+06,"1466350299188775374": 1.4706997550482107e+06}
2017-11-03T02:45:48.528+04:00 [Info] connected with 1 indexers
2017-11-03T02:45:48.528+04:00 [Info] GSIC[default/pamain-1509634068408973674] logstats "pamain" {"gsi_scan_count":2328,"gsi_scan_duration":3836150025,"gsi_throttle_duration":930448,"gsi_prime_duration":3591640962,"gsi_blocked_duration":0,"gsi_totalbackfills":0}
2017-11-03T02:45:48.528+04:00 [Info] index 1466350299188775374 has 1 replicas
2017-11-03T02:45:48.528+04:00 [Info] index 14822891103662477751 has 1 replicas
2017-11-03T02:45:48.528+04:00 [Info] client load stats {"14822891103662477751": 1.6967825544616883e+06,"1466350299188775374": 1.4381548775241054e+06}
2017-11-03T02:46:48.528+04:00 [Info] connected with 1 indexers
2017-11-03T02:46:48.528+04:00 [Info] index 1466350299188775374 has 1 replicas
2017-11-03T02:46:48.528+04:00 [Info] index 14822891103662477751 has 1 replicas
2017-11-03T02:46:48.528+04:00 [Info] client load stats {"14822891103662477751": 1.6967825544616883e+06,"1466350299188775374": 1.4660464387620527e+06}
2017-11-03T02:46:48.528+04:00 [Info] GSIC[default/pamain-1509634068408973674] logstats "pamain" {"gsi_scan_count":2329,"gsi_scan_duration":3837703021,"gsi_throttle_duration":930448,"gsi_prime_duration":3593124106,"gsi_blocked_duration":0,"gsi_totalbackfills":0}
_time=2017-11-03T02:46:54.057+04:00 _level=ERROR _msg=PrimaryScan.newIndexConnection  error=System datastore error  - cause: This bucket type is not supported memcached
_time=2017-11-03T02:46:54.181+04:00 _level=ERROR _msg=PrimaryScan.newIndexConnection  error=System datastore error  - cause: This bucket type is not supported memcached
_time=2017-11-03T02:46:54.228+04:00 _level=ERROR _msg=PrimaryScan.newIndexConnection  error=System datastore error  - cause: This bucket type is not supported memcached
_time=2017-11-03T02:46:57.429+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.431+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.433+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.433+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.433+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.433+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.441+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.441+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.441+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.441+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.441+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.444+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.444+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.446+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.446+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.446+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.446+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.446+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.446+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.446+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.446+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.446+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.446+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.446+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.448+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.448+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.455+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.455+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.455+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.455+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.456+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.456+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.459+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.459+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.459+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.459+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.459+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.459+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.467+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
_time=2017-11-03T02:46:57.467+04:00 _level=WARN _msg=Finalizing a bucket with active connections.
2017-11-03T02:47:48.528+04:00 [Info] connected with 1 indexers
2017-11-03T02:47:48.528+04:00 [Info] index 1466350299188775374 has 1 replicas
2017-11-03T02:47:48.528+04:00 [Info] index 14822891103662477751 has 1 replicas
2017-11-03T02:47:48.528+04:00 [Info] client load stats {"14822891103662477751": 1.6967825544616883e+06,"1466350299188775374": 1.4660464387620527e+06}
2017-11-03T02:48:48.528+04:00 [Info] connected with 1 indexers
2017-11-03T02:48:48.528+04:00 [Info] index 1466350299188775374 has 1 replicas
2017-11-03T02:48:48.528+04:00 [Info] GSIC[default/pamain-1509634068408973674] logstats "pamain" {"gsi_scan_count":2330,"gsi_scan_duration":3839216369,"gsi_throttle_duration":930448,"gsi_prime_duration":3594589996,"gsi_blocked_duration":0,"gsi_totalbackfills":0}
2017-11-03T02:48:48.528+04:00 [Info] index 14822891103662477751 has 1 replicas
2017-11-03T02:48:48.528+04:00 [Info] client load stats {"14822891103662477751": 1.6967825544616883e+06,"1466350299188775374": 1.4613242193810265e+06}

Im not sure if this log is related to my query

If I execute this query using Web UI I gate Gateway Timeout error:

{
  "status": "Gateway Timeout",
  "status_detail": "The query workbench only supports queries running for 300 seconds. Use cbq from the command-line for longer running queries. Certain DML queries, such as index creation, will continue in the background despite the user interface timeout."
}

and when I run the query with cbq it never finishes.

Why is System datastore error caused?

“System datastore error” is not caught by Web UI, CLI or RXJava client.

vsr1 · November 2, 2017, 10:59pm

Check the following query is working
SELECT META().id FROM pamain;

Is other queries working? If none of them working restart the instance and try again.

Rabzu · November 2, 2017, 11:02pm

Its working.

Non of the queries work. I forgot to add after a restart CB works fine for some time period but the then it starts the same behaviour

vsr1 · November 2, 2017, 11:03pm

You should try with CB 4.6.3. Non-covered queries use hang occasionally you might be hitting that and has been fixed in 4.6.3

johan_larson · November 3, 2017, 1:45pm

Also, how much memory have your configured for your system? I’m wondering if you are running into some sort of memory bounds.

Rabzu · November 3, 2017, 3:26pm

Data Service = 8423
Index Service = 5000
Search Service= 5130

I updated to v=5 and it seems to work now, although sometimes some of the queries are not responding

Rabzu · November 5, 2017, 8:27pm

Looks like updating CB to v5 didn’t quite help

It still takes really long time to execute. How can we check if we are running into memory bounds?

btw indexing is correct:
success | elapsed: 38.26s | execution: 38.26s | count: 4 | size: 3789438

{
  "plan": {
    "#operator": "Sequence",
    "~children": [
      {
        "#operator": "UnionScan",
        "scans": [
          {
            "#operator": "IndexScan2",
            "index": "idx_publisherTenantId_screengroup",
            "index_id": "7739d4703ab1c49f",
            "index_projection": {
              "primary_key": true
            },
            "keyspace": "pamain",
            "namespace": "default",
            "spans": [
              {
                "exact": true,
                "range": [
                  {
                    "high": "\"6058ff09-125b-4bba-899c-3a2064d56527\"",
                    "inclusion": 3,
                    "low": "\"6058ff09-125b-4bba-899c-3a2064d56527\""
                  }
                ]
              }
            ],
            "using": "gsi"
          },
          {
            "#operator": "DistinctScan",
            "scan": {
              "#operator": "IndexScan2",
              "index": "idx_publisherIds_screengroup",
              "index_id": "6e95641e0cc36b90",
              "index_projection": {
                "primary_key": true
              },
              "keyspace": "pamain",
              "namespace": "default",
              "spans": [
                {
                  "exact": true,
                  "range": [
                    {
                      "high": "\"6058ff09-125b-4bba-899c-3a2064d56527\"",
                      "inclusion": 3,
                      "low": "\"6058ff09-125b-4bba-899c-3a2064d56527\""
                    }
                  ]
                }
              ],
              "using": "gsi"
            }
          }
        ]
      },
      {
        "#operator": "Fetch",
        "keyspace": "pamain",
        "namespace": "default"
      },
      {
        "#operator": "Parallel",
        "~child": {
          "#operator": "Sequence",
          "~children": [
            {
              "#operator": "Filter",
              "condition": "(((((`pamain`.`publisherTenantId`).`value`) = \"6058ff09-125b-4bba-899c-3a2064d56527\") and ((`pamain`.`doc`) = \"ScreenGroup\")) or (any `p` in (`pamain`.`publisherIds`) satisfies ((`p`.`value`) = \"6058ff09-125b-4bba-899c-3a2064d56527\") end and ((`pamain`.`doc`) = \"ScreenGroup\")))"
            },
            {
              "#operator": "InitialProject",
              "result_terms": [
                {
                  "expr": "self",
                  "star": true
                },
                {
                  "expr": "(meta(`pamain`).`cas`)"
                }
              ]
            },
            {
              "#operator": "FinalProject"
            }
          ]
        }
      }
    ]
  },
  "text": "SELECT *, meta().cas FROM `pamain` USE INDEX (`idx_publisherTenantId_screengroup`,`idx_publisherIds_screengroup`) WHERE publisherTenantId.`value` = \"6058ff09-125b-4bba-899c-3a2064d56527\" AND doc = \"ScreenGroup\" OR ANY p IN publisherIds SATISFIES p.`value` = \"6058ff09-125b-4bba-899c-3a2064d56527\" END AND doc = \"ScreenGroup\""
}

vsr1 · November 6, 2017, 4:01am

It looks like your document is 1MB in size. The plan looks right. You can enable profiling and see where it taking time.
https://blog.couchbase.com/optimize-n1ql-performance-using-request-profiling/

Rabzu · November 6, 2017, 11:04am

I think profiling is only for enterprise version. We have community version first. There are only 200 documents in the CB and if takes 40s to retrieve an indexed DB Im not sure we will be moving to enterprise version. Unless we are doing something fundamentally wrong.

vsr1 · November 6, 2017, 1:21pm

Project only META().id and check how long it takes

How much memory do you have on the machine? Above services already taken 18GB. Do you have enough memory to run the process and query service.

johan_larson · November 6, 2017, 1:34pm

What are your index definitions?

Rabzu · November 6, 2017, 2:07pm

[
  {
    "indexes": {
      "condition": "(`doc` = \"AdView\")",
      "datastore_id": "http://127.0.0.1:8091",
      "id": "374bede53fa99340",
      "index_key": [
        "(`advertiserId`.`value`)",
        "`deleted`"
      ],
      "keyspace_id": "pamain",
      "name": "idx_advertiserId_adview",
      "namespace_id": "default",
      "state": "online",
      "using": "gsi"
    }
  },
  {
    "indexes": {
      "condition": "(`doc` = \"ScreenGroup\")",
      "datastore_id": "http://127.0.0.1:8091",
      "id": "6e95641e0cc36b90",
      "index_key": [
        "(distinct (array (`p`.`value`) for `p` in `publisherIds` end))"
      ],
      "keyspace_id": "pamain",
      "name": "idx_publisherIds_screengroup",
      "namespace_id": "default",
      "state": "online",
      "using": "gsi"
    }
  },
  {
    "indexes": {
      "condition": "(`doc` = \"ActivationToken\")",
      "datastore_id": "http://127.0.0.1:8091",
      "id": "fa85e46b5f9cdfe1",
      "index_key": [
        "(`tenantId`.`value`)"
      ],
      "keyspace_id": "pamain",
      "name": "idx_tenantId_activationToken",
      "namespace_id": "default",
      "state": "online",
      "using": "gsi"
    }
  },
  {
    "indexes": {
      "condition": "(`doc` = \"AppView\")",
      "datastore_id": "http://127.0.0.1:8091",
      "id": "5e0197fc8dd47dcc",
      "index_key": [
        "(`advertiserId`.`value`)",
        "`deleted`"
      ],
      "keyspace_id": "pamain",
      "name": "idx_advertiserId_appView",
      "namespace_id": "default",
      "state": "online",
      "using": "gsi"
    }
  },
  {
    "indexes": {
      "datastore_id": "http://127.0.0.1:8091",
      "id": "cdb57cec7a1991b7",
      "index_key": [],
      "is_primary": true,
      "keyspace_id": "pamain",
      "name": "#primary",
      "namespace_id": "default",
      "state": "online",
      "using": "gsi"
    }
  },
  {
    "indexes": {
      "condition": "(`doc` = \"AppTemplateMetadata\")",
      "datastore_id": "http://127.0.0.1:8091",
      "id": "99c7c10ae8c94496",
      "index_key": [
        "(`developerTenantId`.`value`)",
        "`deleted`"
      ],
      "keyspace_id": "pamain",
      "name": "idx_developerTenantId_apptemplate",
      "namespace_id": "default",
      "state": "online",
      "using": "gsi"
    }
  },
  {
    "indexes": {
      "condition": "(`doc` = \"AssetMetadataView\")",
      "datastore_id": "http://127.0.0.1:8091",
      "id": "9b844eabbf9f2763",
      "index_key": [
        "(`advertiserId`.`value`)",
        "`deleted`"
      ],
      "keyspace_id": "pamain",
      "name": "idx_advertiserId_AssetMetadata",
      "namespace_id": "default",
      "state": "online",
      "using": "gsi"
    }
  },
  {
    "indexes": {
      "condition": "(`doc` = \"ScreenGroup\")",
      "datastore_id": "http://127.0.0.1:8091",
      "id": "62b369962195ea80",
      "index_key": [
        "(distinct (array ((`p`.`id`).`value`) for `p` in `players` end))"
      ],
      "keyspace_id": "pamain",
      "name": "idx_playerId",
      "namespace_id": "default",
      "state": "online",
      "using": "gsi"
    }
  },
  {
    "indexes": {
      "condition": "(`doc` = \"ScreenGroup\")",
      "datastore_id": "http://127.0.0.1:8091",
      "id": "7739d4703ab1c49f",
      "index_key": [
        "(`publisherTenantId`.`value`)"
      ],
      "keyspace_id": "pamain",
      "name": "idx_publisherTenantId_screengroup",
      "namespace_id": "default",
      "state": "online",
      "using": "gsi"
    }
  },
  {
    "indexes": {
      "condition": "(`doc` = \"AppTemplateMetadata\")",
      "datastore_id": "http://127.0.0.1:8091",
      "id": "536aedf5d16f0e0d",
      "index_key": [
        "`public`",
        "`deleted`"
      ],
      "keyspace_id": "pamain",
      "name": "idx_public_apptemplate",
      "namespace_id": "default",
      "state": "online",
      "using": "gsi"
    }
  },
  {
    "indexes": {
      "condition": "(`doc` = \"CampaignTemplate\")",
      "datastore_id": "http://127.0.0.1:8091",
      "id": "cc23a75bc98b223",
      "index_key": [
        "(`advertiserId`.`value`)",
        "`deleted`"
      ],
      "keyspace_id": "pamain",
      "name": "idx_advertiserId_CampaignTemplate",
      "namespace_id": "default",
      "state": "online",
      "using": "gsi"
    }
  },
  {
    "indexes": {
      "condition": "(`doc` = \"ScreenGroup\")",
      "datastore_id": "http://127.0.0.1:8091",
      "id": "492f5c0da4abc283",
      "index_key": [
        "(distinct (array ((`p`.`token`).`value`) for `p` in `players` end))"
      ],
      "keyspace_id": "pamain",
      "name": "idx_player_token",
      "namespace_id": "default",
      "state": "online",
      "using": "gsi"
    }
  }
]

Rabzu · November 6, 2017, 2:09pm

We actually have 40gb but we now reduced it to and result is the same.
Data Service = 8423
Index Service = 500
Search Service= 513

We will try Project only META().id now

btw we are running the same queries and indexes on a different CB instance with 10 records and it works fine

Rabzu · November 6, 2017, 5:13pm

“status”: “success”,
“metrics”: {
“elapsedTime”: “49.247475ms”,
“executionTime”: “49.233691ms”,
“resultCount”: 9,
“resultSize”: 18
}

vsr1 · November 6, 2017, 5:29pm

Can you try original query in cbq shell.
Also can use you try using USE KEYS from the documents that return META().id to isolate problem. Also try with one document id with USE KEYS

Rabzu · November 6, 2017, 5:46pm

1.Original query in cbq:

 "status": "success",
    "metrics": {
        "elapsedTime": "1.285069316s",
        "executionTime": "1.2850522s",
        "resultCount": 9,
        "resultSize": 3102213
    }
}

I tried this

SELECT *, meta().id FROM pamain USE KEYS[“ScreenGroup_d1eb3b39-6a74-46aa-9223-e28bf75d17fb”, “ScreenGroup_bdfe83d9-da1d-4f67-9426-c05514252377”,“ScreenGroup_b3eb1bbf-6efc-4faa-ab26-cb0e6d95e80e”,“ScreenGroup_b3eb1bbf-6efc-4faa-ab26-cb0e6d95e80e”,“ScreenGroup_9d9622e9-5e07-4e52-8bf4-acd6b72a4f20”,“ScreenGroup_9d9622e9-5e07-4e52-8bf4-acd6b72a4f20”,“ScreenGroup_5ac8a836-8262-4512-8435-e6d6f5436fe3”,“ScreenGroup_4b54be1d-948c-4f2f-91b0-823875b04ac6”,“ScreenGroup_c499be3d-a336-4d37-a037-e12a1f166c13”,“ScreenGroup_0ce298a2-13f2-4974-a206-93166902dad4”] WHERE publisherTenantId.value = “6058ff09-125b-4bba-899c-3a2064d56527” AND doc = “ScreenGroup” OR ANY p IN publisherIds SATISFIES p.value = “6058ff09-125b-4bba-899c-3a2064d56527” END AND doc = “ScreenGroup”;

“status”: “success”,
“metrics”: {
“elapsedTime”: “459.864287ms”,
“executionTime”: “459.841925ms”,
“resultCount”: 10,
“resultSize”: 2376014
}
}

Not Sure if this is what you asked

SELECT meta().id FROM pamain USE KEYS[“ScreenGroup_0ce298a2-13f2-4974-a206-93166902dad4”] WHERE publisherTenantId.value = “6058ff09-125b-4bba-899c-3a2064d56527” AND doc = “ScreenGroup” OR ANY p IN publisherIds SATISFIES p.value = “6058ff09-125b-4bba-899c-3a2064d56527” END AND doc = “ScreenGroup”;

{
“requestID”: “e3a3697a-3009-4b1d-b018-90f57b80bd81”,
“signature”: {
“id”: “json”
},
“results”: [
{
“id”: “ScreenGroup_0ce298a2-13f2-4974-a206-93166902dad4”
}
],
“status”: “success”,
“metrics”: {
“elapsedTime”: “14.613778ms”,
“executionTime”: “14.594287ms”,
“resultCount”: 1,
“resultSize”: 80
}
}

vsr1 · November 6, 2017, 5:57pm

The query only takes around sec and it is transferring 3MB data.

Rabzu · November 6, 2017, 6:00pm

So you suggest I should change the model in order to reduce its size for faster retrieval?
we tested similar size object on Oracle and it took around 0.1s to retrieve