We now notice that for ANY query that includes a correlated subquery, not only does Plan Text throw errors in the console, but we get very poor performance, seemingly regardless of indexing.
Here’s another example of a very poorly performing query (there are about 20 signature_forms and about 6000 choices:
SELECT a.*, META().id AS metaid,
(SELECT RAW b.label
FROM demo b
WHERE b.type='choice'
AND b.code = a.code
)[0] AS _signature_reason_label
FROM demo a
WHERE a.type = 'signature_form'
AND (archived IS MISSING
OR archived = NULL
OR archived = FALSE)
Yields the following results (only available via cbq \set -profile "timings";, as the console throws an error):
"status": "success",
"metrics": {
"elapsedTime": "8.375158915s",
"executionTime": "8.375057474s",
"resultCount": 32,
"resultSize": 52105,
"serviceLoad": 3
},
"profile": {
"phaseTimes": {
"authorize": "16.87µs",
"fetch": "7.911489904s",
"filter": "3.16878583s",
"indexScan": "595.341227ms",
"instantiate": "25.87µs",
"parse": "2.294214ms",
"plan": "2.957318ms",
"run": "8.369754722s"
},
"phaseCounts": {
"fetch": 388200,
"filter": 86,
"indexScan": 388214
},
"phaseOperators": {
"authorize": 1,
"fetch": 33,
"filter": 33,
"indexScan": 34
},
"requestTime": "2022-06-23T17:25:12.264Z",
"servicingHost": "172.31.16.198:8091",
"executionTimings": {
"#operator": "Authorize",
"#stats": {
"#phaseSwitches": 4,
"execTime": "1.64µs",
"servTime": "15.23µs"
},
"privileges": {
"List": [
{
"Target": "default:demo",
"Priv": 7,
"Props": 0
}
]
},
"~child": {
"#operator": "Sequence",
"#stats": {
"#phaseSwitches": 2,
"execTime": "1.09µs"
},
"~children": [
{
"#operator": "UnionScan",
"#stats": {
"#itemsIn": 54,
"#itemsOut": 40,
"#phaseSwitches": 195,
"execTime": "28.86µs",
"kernTime": "1.024047ms"
},
"scans": [
{
"#operator": "IndexScan3",
"#stats": {
"#heartbeatYields": 4,
"#itemsOut": 40,
"#phaseSwitches": 165,
"execTime": "53.18µs",
"kernTime": "190.191µs",
"servTime": "709.564µs"
},
"as": "a",
"index": "idx_type",
"index_id": "aec17a28a074149b",
"index_projection": {
"primary_key": true
},
"keyspace": "demo",
"namespace": "default",
"spans": [
{
"exact": true,
"range": [
{
"high": "\"signature_form\"",
"inclusion": 3,
"low": "\"signature_form\""
}
]
}
],
"using": "gsi"
},
{
"#operator": "IndexScan3",
"#stats": {
"#heartbeatYields": 1,
"#itemsOut": 14,
"#phaseSwitches": 61,
"execTime": "47.102µs",
"kernTime": "9.08µs",
"servTime": "980.355µs"
},
"as": "a",
"index": "idx_signature_form_archived",
"index_id": "f6e08d771c0d0b9e",
"index_projection": {
"primary_key": true
},
"keyspace": "demo",
"namespace": "default",
"spans": [
{
"exact": true,
"range": [
{
"high": "false",
"inclusion": 3,
"low": "false"
}
]
}
],
"using": "gsi"
}
]
},
{
"#operator": "Fetch",
"#stats": {
"#heartbeatYields": 2,
"#itemsIn": 40,
"#itemsOut": 40,
"#phaseSwitches": 168,
"execTime": "83.811µs",
"kernTime": "1.017026ms",
"servTime": "1.369189ms"
},
"as": "a",
"keyspace": "demo",
"namespace": "default"
},
{
"#operator": "Sequence",
"#stats": {
"#phaseSwitches": 2,
"execTime": "340.302µs",
"kernTime": "110ns",
"state": "running"
},
"~children": [
{
"#operator": "Filter",
"#stats": {
"#heartbeatYields": 1,
"#itemsIn": 40,
"#itemsOut": 32,
"#phaseSwitches": 148,
"execTime": "1.018596ms",
"kernTime": "1.859422ms"
},
"condition": "(((`a`.`type`) = \"signature_form\") and ((((`a`.`archived`) is missing) or ((`a`.`archived`) = null)) or ((`a`.`archived`) = false)))"
},
{
"#operator": "InitialProject",
"#stats": {
"#itemsIn": 32,
"#itemsOut": 32,
"#phaseSwitches": 102,
"execTime": "8.366478145s",
"kernTime": "1.66075ms"
},
"result_terms": [
{
"expr": "`a`",
"star": true
},
{
"as": "metaid",
"expr": "(meta(`a`).`id`)"
},
{
"as": "_signature_reason_label",
"expr": "(correlated (select raw (`b`.`label`) from `default`:`demo` as `b` where (((`b`.`type`) = \"choice\") and ((`b`.`code`) = (`a`.`code`))))[0])"
}
]
}
]
},
{
"#operator": "Stream",
"#stats": {
"#itemsIn": 32,
"#itemsOut": 32,
"#phaseSwitches": 34,
"execTime": "1.492897ms"
}
}
]
},
"~versions": [
"7.0.2-N1QL",
"7.0.2-6703-enterprise"
]
}
}
}
Notice the initialProject takes 8 seconds despite only 32 in and 32 out.
Index advisor says:
CREATE INDEX idx_type ON `demo`(`type`)
CREATE INDEX idx_signature_form_archived ON `demo`(`archived`) WHERE (`type` = 'signature_form')
and Existing indexes are sufficient
If I remove the subquery, performance returns and I can then click Plan Text in the console:
{
"#operator": "Authorize",
"#stats": {
"#phaseSwitches": 4,
"execTime": "1.4µs",
"servTime": "1.117773ms"
},
"privileges": {
"List": [
{
"Target": "default:demo",
"Priv": 7,
"Props": 0
}
]
},
"~child": {
"#operator": "Sequence",
"#stats": {
"#phaseSwitches": 2,
"execTime": "1.67µs"
},
"~children": [
{
"#operator": "UnionScan",
"#stats": {
"#itemsIn": 54,
"#itemsOut": 40,
"#phaseSwitches": 195,
"execTime": "26.541µs",
"kernTime": "1.012751ms"
},
"scans": [
{
"#operator": "IndexScan3",
"#stats": {
"#heartbeatYields": 4,
"#itemsOut": 40,
"#phaseSwitches": 165,
"execTime": "41.57µs",
"kernTime": "69.651µs",
"servTime": "879.39µs"
},
"as": "a",
"index": "idx_type",
"index_id": "aec17a28a074149b",
"index_projection": {
"primary_key": true
},
"keyspace": "demo",
"namespace": "default",
"spans": [
{
"exact": true,
"range": [
{
"high": "\"signature_form\"",
"inclusion": 3,
"low": "\"signature_form\""
}
]
}
],
"using": "gsi",
"#time_normal": "00:00.000",
"#time_absolute": 0.00092096
},
{
"#operator": "IndexScan3",
"#stats": {
"#heartbeatYields": 1,
"#itemsOut": 14,
"#phaseSwitches": 61,
"execTime": "18.51µs",
"kernTime": "22.82µs",
"servTime": "875.83µs"
},
"as": "a",
"index": "idx_signature_form_archived",
"index_id": "f6e08d771c0d0b9e",
"index_projection": {
"primary_key": true
},
"keyspace": "demo",
"namespace": "default",
"spans": [
{
"exact": true,
"range": [
{
"high": "false",
"inclusion": 3,
"low": "false"
}
]
}
],
"using": "gsi",
"#time_normal": "00:00.000",
"#time_absolute": 0.0008943400000000001
}
],
"#time_normal": "00:00.000",
"#time_absolute": 0.000026541
},
{
"#operator": "Fetch",
"#stats": {
"#heartbeatYields": 2,
"#itemsIn": 40,
"#itemsOut": 40,
"#phaseSwitches": 168,
"execTime": "102.641µs",
"kernTime": "1.181293ms",
"servTime": "1.590768ms"
},
"as": "a",
"keyspace": "demo",
"namespace": "default",
"#time_normal": "00:00.001",
"#time_absolute": 0.001693409
},
{
"#operator": "Sequence",
"#stats": {
"#phaseSwitches": 2,
"execTime": "276.213µs",
"kernTime": "70ns",
"state": "running"
},
"~children": [
{
"#operator": "Filter",
"#stats": {
"#itemsIn": 40,
"#itemsOut": 32,
"#phaseSwitches": 148,
"execTime": "895.71µs",
"kernTime": "2.296075ms"
},
"condition": "(((`a`.`type`) = \"signature_form\") and ((((`a`.`archived`) is missing) or ((`a`.`archived`) = null)) or ((`a`.`archived`) = false)))",
"#time_normal": "00:00.000",
"#time_absolute": 0.0008957100000000001
},
{
"#operator": "InitialProject",
"#stats": {
"#itemsIn": 32,
"#itemsOut": 32,
"#phaseSwitches": 102,
"execTime": "848.462µs",
"kernTime": "1.929891ms"
},
"result_terms": [
{
"expr": "`a`",
"star": true
},
{
"as": "metaid",
"expr": "(meta(`a`).`id`)"
}
],
"#time_normal": "00:00.000",
"#time_absolute": 0.000848462
}
],
"#time_normal": "00:00.000",
"#time_absolute": 0.00027621300000000003
},
{
"#operator": "Stream",
"#stats": {
"#itemsIn": 32,
"#itemsOut": 32,
"#phaseSwitches": 34,
"execTime": "729.766µs"
},
"#time_normal": "00:00.000",
"#time_absolute": 0.000729766
}
],
"#time_normal": "00:00.000",
"#time_absolute": 0.0000016699999999999999
},
"~versions": [
"7.0.2-N1QL",
"7.0.2-6703-enterprise"
],
"#time_normal": "00:00.001",
"#time_absolute": 0.0011191729999999998
}
sorry, I meant stacks, not stats!