Why is query engine filtering on indexed fields?

SQL++
1

I have been investigating query timings to assess indexing strategies, and have noticed that the query engine seems to be filtering on fields from the WHERE clause that were already used in the index scan. This seemingly-redundant filtering is not insignificant and can a significant percentage of total execution time, increasing proportionally with the number of results in the Filter input set.

In a contrived test I created an array index:

CREATE INDEX idx_array_test ON web_api(DISTINCT things);

I then inserted 375 documents, and ran the following query:

SELECT META().id, things
FROM web_api
WHERE ANY x in things SATISFIES x=27 END;

This query averages around 12ms with 242 results, and the execution plan shows 13-40% (typically 20%) of time spent in the Filter operator.

Why is this happening? Does the query optimiser not realise this filtering is redundant?

This was measured with Couchbase Enterprise 5.1.1 build 5723 obtained from Docker hub, Couchbase bucket type with 1GB memory quota, single node cluster and full ejection method.

Sample plan text is below:

{
  "#operator": "Sequence",
  "#stats": {
    "#phaseSwitches": 2,
    "execTime": "651ns",
    "kernTime": "11.365961ms"
  },
  "~children": [
    {
      "#operator": "Authorize",
      "#stats": {
        "#phaseSwitches": 4,
        "execTime": "1.393µs",
        "kernTime": "10.558929ms",
        "servTime": "789.872µs"
      },
      "privileges": {
        "List": [
          {
            "Target": "default:web_api",
            "Priv": 7
          }
        ]
      },
      "~child": {
        "#operator": "Sequence",
        "#stats": {
          "#phaseSwitches": 3,
          "execTime": "2.07µs",
          "kernTime": "10.552456ms"
        },
        "~children": [
          {
            "#operator": "DistinctScan",
            "#stats": {
              "#itemsIn": 242,
              "#itemsOut": 242,
              "#phaseSwitches": 971,
              "execTime": "139.101µs",
              "kernTime": "62.691µs",
              "servTime": "1.113646ms"
            },
            "scan": {
              "#operator": "IndexScan2",
              "#stats": {
                "#itemsOut": 242,
                "#phaseSwitches": 973,
                "execTime": "277.512µs",
                "kernTime": "86.599µs",
                "servTime": "790.283µs"
              },
              "index": "idx_array_test",
              "index_id": "2f231e73ac47026a",
              "index_projection": {
                "primary_key": true
              },
              "keyspace": "web_api",
              "namespace": "default",
              "spans": [
                {
                  "exact": true,
                  "range": [
                    {
                      "high": "27",
                      "inclusion": 3,
                      "low": "27"
                    }
                  ]
                }
              ],
              "using": "gsi",
              "#time_normal": "00:00.0010",
              "#time_absolute": 0.001067795
            },
            "#time_normal": "00:00.0012",
            "#time_absolute": 0.0012527469999999998
          },
          {
            "#operator": "Fetch",
            "#stats": {
              "#itemsIn": 242,
              "#itemsOut": 242,
              "#phaseSwitches": 977,
              "execTime": "488.294µs",
              "kernTime": "1.036971ms",
              "servTime": "4.517499ms"
            },
            "keyspace": "web_api",
            "namespace": "default",
            "#time_normal": "00:00.0050",
            "#time_absolute": 0.005005793000000001
          },
          {
            "#operator": "Sequence",
            "#stats": {
              "#phaseSwitches": 5,
              "execTime": "1.703µs",
              "kernTime": "10.539188ms"
            },
            "~children": [
              {
                "#operator": "Filter",
                "#stats": {
                  "#itemsIn": 242,
                  "#itemsOut": 242,
                  "#phaseSwitches": 973,
                  "execTime": "2.635735ms",
                  "kernTime": "6.112176ms"
                },
                "condition": "any `x` in (`web_api`.`things`) satisfies (`x` = 27) end",
                "#time_normal": "00:00.0026",
                "#time_absolute": 0.0026357349999999997
              },
              {
                "#operator": "InitialProject",
                "#stats": {
                  "#itemsIn": 242,
                  "#itemsOut": 242,
                  "#phaseSwitches": 973,
                  "execTime": "1.011397ms",
                  "kernTime": "7.782108ms"
                },
                "result_terms": [
                  {
                    "expr": "(meta(`web_api`).`id`)"
                  },
                  {
                    "expr": "(`web_api`.`things`)"
                  }
                ],
                "#time_normal": "00:00.0010",
                "#time_absolute": 0.001011397
              },
              {
                "#operator": "FinalProject",
                "#stats": {
                  "#itemsIn": 242,
                  "#itemsOut": 242,
                  "#phaseSwitches": 975,
                  "execTime": "142.634µs",
                  "kernTime": "10.387341ms"
                },
                "#time_normal": "00:00.0001",
                "#time_absolute": 0.000142634
              }
            ],
            "#time_normal": "00:00.0000",
            "#time_absolute": 0.000001703
          }
        ],
        "#time_normal": "00:00.0000",
        "#time_absolute": 0.0000020699999999999997
      },
      "#time_normal": "00:00.0007",
      "#time_absolute": 0.000791265
    },
    {
      "#operator": "Stream",
      "#stats": {
        "#itemsIn": 242,
        "#itemsOut": 242,
        "#phaseSwitches": 491,
        "execTime": "19.976µs",
        "kernTime": "11.340177ms"
      },
      "#time_normal": "00:00.0000",
      "#time_absolute": 0.000019976
    }
  ],
  "~versions": [
    "2.0.0-N1QL",
    "5.1.1-5723-enterprise"
  ],
  "#time_normal": "00:00",
  "#time_absolute": 0
}
2

Filters are always re-applied even those are pushed to indexScan.

  1. Filters may not be exactly translated to spans/ranges.
  2. IndexScan can return the false positives.
  3. Only part of filters might be pushed to index scan
  4. Filters can be complex
  5. query might be doing Fetch in that case filters needs to be re applied because index lags behind and document may have changed.
3

Thanks for the response @vsr1.

I don’t understand #2, unless it’s the same as #5. When would an index return a false positive? How would covering indexes work at all if the index were unreliable?

Although I understand filters may not always be satisfied by the index, it seems a really obvious, overlooked optimisation to pass data through a redundant O(n) filter. Taking 25-40% of total query execution time to do so is not insignificant.

For #5: ensuring query-index consistency is up to me, the query executor. For queries where I need consistency we can set one of the consistency options; to re-filter at the data node overrides that being my decision. And again, it would suggest inconsistent results where a covering index is used.

Overall your points all seem to be inconsistent with the use of covering indexes, and indicate that Couchbase query engine has a built-in O(n) time-waster that can add more than 25% overhead on execution times reading, regardless of my indexing strategy.

4

BUMP

You’ve indicated that the query engine omits a significant optimisation, and more worryingly, that the indexing service can return incorrect results.

I’d really appreciate clarification of these behaviours of Couchbase please.

5

Couchbase Index Scans are based on Range Scans(Understanding Index Scans in Couchbase N1QL Query)
Query predicate can be complex and every predicate can’t be easily converted to exactly to range. In that situation supper set of ranges will be generated to give right results… In that situations indexer can give super set of data than query predicate(false positives).

Example : 
       CREATE INDEX ix1 ON default(c1);
       SELECT META().id FROM default WHERE lower(c1) = "xyz";

In above example index key is c1 and query predicate is on lower(c1). Index have entries only on c1. In this case predicate to range translation is not exactly possible (Unless apply inverse function. every case can’t possible inverse). In that case query service generates range for all values (not including MISSING/NULL). Then query service applies predicate and eliminates not satisfied values.

This all functionality of each service and where things are handled. Not giving incorrect results of lower level module.

Index maintains asynchronously (lags few milliseconds behind from Data node). For non-covered query, it required Fetch, If predicates are passed to indexer and got document keys and does Fetch. In meantime some one changed document (predicate value, which can evaluate to false). If predicate not applied the document returns to user. This can result in wrong results. Due to that predicate is re-applied.

If the predicate is exactly translated, covered query in some cases can be optimized further. At present N1QL gives importance to right results vs performance. In certain situations it can be further optimized.
Hope this gives clarification. cc @keshav_m

6

Thanks @vsr1, that’s much clearer :slight_smile:

Is enhancing the query planner to avoid redundant re-application of predicates when possible scheduled for a future release yet?

7

Yes. Can be tracked using MB-30660