Tracing queries and how to find execution timings etc

SQL++
1

I am trying to find how to find running and completed queries in CB 5.0, and came across following link. Would you recommend to use this as the best way to get these queries, and secondly to find execution timings, is says to use executionTime - which sequence to use as executionTime is present for other phases or operators -

SELECT *, meta().plan FROM system:active_requests;
[
{
“active_requests”: {
“clientContextID”: “e6e81ad9-09b6-4c98-987a-a80947cbf4cd”,
“elapsedTime”: “22.361384ms”,
“executionTime”: “22.336681ms”,
“node”: “127.0.0.1:8091”,
“phaseCounts”: {
“primaryScan”: 1

From

https://developer.couchbase.com/documentation/server/current/monitoring/monitoring-n1ql-query.html#topic_nvs_ghr_dz

Lastly is there a way to get queries which take more than x ms etc ?

Thanks.

2

All of them possible. Please check out https://blog.couchbase.com/optimize-n1ql-performance-using-request-profiling/

3

Thanks! One more thing, trying to find execution timings for a statement, there are various sections in the json output , which says executionTime, execTime (kind of similar words) - which section shall I be looking for actually knowing the execution timing it too to execute the statement… sample output:

cbq> SELECT * FROM `travel-sample` WHERE type = "airline" LIMIT 1;
{
    "requestID": "96d8977c-6fad-4773-94df-507a904e38be",
    "signature": {
        "*": "*"
    },
    "results": [
        {
            "travel-sample": {
                "callsign": "AXW",
                "country": "United States",
                "iata": "TQ",
                "icao": "AXW",
                "id": 10125,
                "name": "Ajay Wings",
                "type": "airline"
            }
        }
    ],
    "status": "success",
    "metrics": {
        "elapsedTime": "3.878174ms",
        "executionTime": "3.862952ms",
        "resultCount": 1,
        "resultSize": 297
    },
    "profile": {
        "phaseTimes": {
	    "authorize": "559.537µs",
	    "fetch": "365.198µs",
	    "indexScan": "1.711685ms",
	    "instantiate": "93.282µs",
	    "parse": "456.113µs",
	    "plan": "319.926µs",
	    "run": "2.934273ms"
	},
        "phaseCounts": {
	    "fetch": 1,
	    "indexScan": 1
	},
        "phaseOperators": {
	    "authorize": 1,
	    "fetch": 1,
	    "indexScan": 1
	},
        "executionTimings": {
	    "#operator": "Sequence",
	    "#stats": {
	        "#phaseSwitches": 2,
	        "execTime": "1.478µs",
	        "kernTime": "2.93114ms"
	    },
	    "~children": [
	        {
	            "#operator": "Authorize",
	            "#stats": {
	                "#phaseSwitches": 4,
	                "execTime": "2.656µs",
	                "kernTime": "2.347997ms",
	                "servTime": "556.881µs"
	            },
	            "privileges": {
	                "List": [
	                    {
	                        "Target": "default:travel-sample",
	                        "Priv": 7
	                    }
	                ]
	            },
	            "~child": {
	                "#operator": "Sequence",
	                "#stats": {
	                    "#phaseSwitches": 3,
	                    "execTime": "3.426µs",
	                    "kernTime": "2.341105ms"
	                },
	                "~children": [
	                    {
	                        "#operator": "Sequence",
	                        "#stats": {
	                            "#phaseSwitches": 2,
	                            "execTime": "2.97µs",
	                            "kernTime": "2.306448ms"
	                        },
	                        "~children": [
	                            {
	                                "#operator": "IndexScan2",
	                                "#stats": {
	                                    "#itemsOut": 1,
	                                    "#phaseSwitches": 7,
	                                    "execTime": "39.997µs",
	                                    "kernTime": "1.266µs",
	                                    "servTime": "1.671688ms"
	                                },
	                                "index": "def_type",
	                                "index_id": "642a89abf042c752",
	                                "index_projection": {
	                                    "primary_key": true
	                                },
	                                "keyspace": "travel-sample",
	                                "limit": "1",
	                                "namespace": "default",
	                                "spans": [
	                                    {
	                                        "exact": true,
	                                        "range": [
	                                            {
	                                                "high": "\"airline\"",
	                                                "inclusion": 3,
	                                                "low": "\"airline\""
	                                            }
	                                        ]
	                                    }
	                                ],
	                                "using": "gsi"
	                            },
	                            {
	                                "#operator": "Fetch",
	                                "#stats": {
	                                    "#itemsIn": 1,
	                                    "#itemsOut": 1,
	                                    "#phaseSwitches": 11,
	                                    "execTime": "23.519µs",
	                                    "kernTime": "1.737899ms",
	                                    "servTime": "341.679µs"
	                                },
	                                "keyspace": "travel-sample",
	                                "namespace": "default"
	                            },
	                            {
	                                "#operator": "Sequence",
	                                "#stats": {
	                                    "#phaseSwitches": 5,
	                                    "execTime": "2.397µs",
	                                    "kernTime": "2.297523ms"
	                                },
	                                "~children": [
	                                    {
	                                        "#operator": "Filter",
	                                        "#stats": {
	                                            "#itemsIn": 1,
	                                            "#itemsOut": 1,
	                                            "#phaseSwitches": 9,
	                                            "execTime": "119.912µs",
	                                            "kernTime": "2.130231ms"
	                                        },
	                                        "condition": "((`travel-sample`.`type`) = \"airline\")"
	                                    },
	                                    {
	                                        "#operator": "InitialProject",
	                                        "#stats": {
	                                            "#itemsIn": 1,
	                                            "#itemsOut": 1,
	                                            "#phaseSwitches": 9,
	                                            "execTime": "7.007µs",
	                                            "kernTime": "2.263662ms"
	                                        },
	                                        "result_terms": [
	                                            {
	                                                "expr": "self",
	                                                "star": true
	                                            }
	                                        ]
	                                    },
	                                    {
	                                        "#operator": "FinalProject",
	                                        "#stats": {
	                                            "#itemsIn": 1,
	                                            "#itemsOut": 1,
	                                            "#phaseSwitches": 11,
	                                            "execTime": "3.94µs",
	                                            "kernTime": "2.283664ms"
	                                        }
	                                    }
	                                ]
	                            }
	                        ]
	                    },
	                    {
	                        "#operator": "Limit",
	                        "#stats": {
	                            "#itemsIn": 1,
	                            "#itemsOut": 1,
	                            "#phaseSwitches": 11,
	                            "execTime": "3.599µs",
	                            "kernTime": "2.323273ms"
	                        },
	                        "expr": "1"
	                    }
	                ]
	            }
	        },
	        {
	            "#operator": "Stream",
	            "#stats": {
	                "#itemsIn": 1,
	                "#itemsOut": 1,
	                "#phaseSwitches": 9,
	                "execTime": "4.154µs",
	                "kernTime": "2.922921ms"
	            }
	        }
	    ],
	    "~versions": [
	        "2.0.0-N1QL",
	        "5.0.1-5003-enterprise"
	    ]
	}
    }
}
4

with or without setting profile options when execute statement at the end it gives metrics
it has execution time that is final time.

“status”: “success”,
“metrics”: {
“elapsedTime”: “3.878174ms”,
“executionTime”: “3.862952ms”,
“resultCount”: 1,
“resultSize”: 297
}

If you want to find which portion of the execution taking you should set profile and each operator. The following is Filter (WHERE clause) operation

{
"#operator": “Filter”,
"#stats": {
"#itemsIn": 1,
"#itemsOut": 1,
"#phaseSwitches": 9,
“execTime”: “119.912µs”,
“kernTime”: “2.130231ms”
},
“condition”: “((travel-sample.type) = “airline”)”
}
5

Thanks, that clarifies! One last question - is there a way to find top 10 queries (lets say by execution time) - something like:

Select *, meta().plan from system:completed_requests where executionTime > ‘X ms’ order by executionTime limit 10 ;

6

As the executionTime is string that can have 1h, 10s , 5ms… you need to use str_to_duration()

Select * from system:completed_requests where str_to_duration(serviceTime) > 5000000  order by str_to_duration(serviceTime) DESC  limit 10 ;

str_to_duration() gives nano seconds https://developer.couchbase.com/documentation/server/current/n1ql/n1ql-language-reference/datefun.html#story-h2-34

Checkout this article it has other examples
https://dzone.com/articles/query-performance-monitoring-made-easy-with-couchb

1 Like
7

Am I doing something wrong here, as the output shows nothing for executionTime:

Select executionTime from system:completed_requests order by str_to_duration(executionTime) DESC limit 10 ;
[
{},
{},
{},
{},
{},
{},
{},
{},
{},
{}
]

Also, I tried:
Select *, meta().plan from system:completed_requests where str_to_duration(executionTime) > 0
order by str_to_duration(executionTime) DESC limit 10 ;

{
“results”: []
}

8

There is no executionTime in system:completed_requests it is serviceTime or elapsedTime

SELECT serviceTime FROM system:completed_requests ORDER BY STR_TO_DURATION(serviceTime) DESC;

9

I see. In that case, for knowing the actual execution time for completed statement, shall I be relying on elapsed time? Thanks!

10

Perhaps, I can use this :

select count(*) num,
min(serviceTime) minEx, max(serviceTime) maxEx,
avg(str_to_duration(serviceTime)/1000000000) avgEx,
statement
from system:completed_requests
where phaseCounts.primaryScan is not missing
group by statement;

This is from the link you shared earlier: