Manage and Monitor Queries
- Capella Operational
Monitoring and profiling SQL++ queries, query service nodes, and corresponding system resources is very important for smoother operational performance and efficiency of the system. In fact, often it is vital for diagnosing and troubleshooting issues such as query performance, resource bottlenecks, and overloading of various services.
System keyspaces provide various monitoring details and statistics about individual queries and the Query service. When running on a cluster with multiple query nodes, stats about all queries on all query nodes are collected in the Query management and monitoring system keyspaces.
For example, this can help identify:
-
The top 10 slow or fast queries running on a particular query node or the cluster.
-
Resource usage statistics of the query service, or resources used for a particular query.
-
Details about the active, completed, and prepared queries.
-
Find long running queries that are running for more than 2 minutes.
These system keyspaces are transient in nature, and are not persisted to disk or permanent storage. Hence, the information in the keyspaces pertains to the current instantiation of the Query service.
You can access the Query management and monitoring system keyspaces using any of the following:
-
SQL++ from the cbq shell or the Query tab
-
A monitoring SDK
Using SQL++ enables you to obtain further insights from the keyspaces.
Authentication and Client Privileges
Users must have permission to access restricted system keyspaces. For more details about cluster credentials, see Configure Cluster Access Credentials.
Monitor System Vitals
The system:vitals
catalog provides data about the running state and health of the query nodes, such as number of logical cores, active threads, queued threads, CPU utilization, memory usage, network utilization, garbage collection percentage, and so on.
This information can be very useful to assess the current workload and performance characteristics of a query node.
Get System Vitals
To view system vitals, use a SQL++ query.
-
SQL++
To view system vitals with SQL++:
SELECT * FROM system:vitals;
System Vitals Details
Getting system vitals, as described in Get System Vitals, returns results similar to the following.
{
"uptime": "7h39m32.668577197s",
"local.time": "2021-04-30 18:42:39.517208807 +0000 UTC m=+27573.945319668",
"version": "7.0.0-N1QL",
"total.threads": 191,
"cores": 2,
"gc.num": 669810600,
"gc.pause.time": "57.586373ms",
"gc.pause.percent": 0,
"memory.usage": 247985184,
"memory.total": 11132383704,
"memory.system": 495554808,
"cpu.user.percent": 0,
"cpu.sys.percent": 0,
"request.completed.count": 140,
"request.active.count": 0,
"request.per.sec.1min": 0.0018,
"request.per.sec.5min": 0.0055,
"request.per.sec.15min": 0.0033,
"request_time.mean": "536.348163ms",
"request_time.median": "54.065567ms",
"request_time.80percentile": "981.869933ms",
"request_time.95percentile": "2.543128455s",
"request_time.99percentile": "4.627922799s",
"request.prepared.percent": 0
}
This catalog contains the following attributes:
Property | Schema | |
---|---|---|
bucket.IO.stats |
The number of reads and retries for each bucket. |
Object |
uptime |
The uptime of the query engine. |
String (duration) |
local.time |
The local time of the query engine. |
Date (date-time) |
version |
The version of the query engine. |
String |
total.threads |
The number of active threads used by the query engine. |
Integer |
cores |
The maximum number of logical cores available to the query engine. |
Integer |
ffdc.total |
The total number of times FFDC has been invoked since the last restart. |
Integer |
gc.num |
The target heap size of the next garbage collection cycle. |
Long (int64) |
gc.pause.time |
The total time spent pausing for garbage collection since the query engine started (ns). |
String (duration) |
gc.pause.percent |
The percentage of time spent pausing for garbage collection since the last time the statistics were checked. |
Long (int64) |
healthy |
False when either the unbounded or plus request queues are full; true otherwise. |
Boolean |
host.memory.free |
Amount of free memory on the host. |
Long (int64) |
host.memory.quota |
The host memory quota. This reflects the node-quota setting. |
Long (int64) |
host.memory.total |
Total memory on the host. |
Long (int64) |
host.memory.value_quota |
This the total document memory quota on the node. |
Long (int64) |
load |
A calculation for how busy the server is. |
Integer |
loadfactor |
The moving 15 minute average of the load calculation. |
Integer |
memory.usage |
The amount of memory allocated for heap objects (bytes). This increases as heap objects are allocated, and decreases as objects are freed. |
Long (int64) |
memory.total |
The cumulative amount of memory allocated for heap objects (bytes). This increases as heap objects are allocated, but does not decrease when objects are freed. |
Long (int64) |
memory.system |
The total amount of memory obtained from the operating system (bytes). This measures the virtual address space reserved by the query engine for heaps, stacks, and other internal data structures. |
Long (int64) |
node |
The name or IP address and port of the node. |
String |
node.allocated.values |
The total number of values allocated to contain documents or computations around documents. (This is only of relevance internally.) |
Integer |
node.memory.usage |
The currently allocated document memory on the node. |
Integer |
cpu.user.percent |
CPU usage. The percentage of time spent executing user code since the last time the statistics were checked. |
Long (int64) |
cpu.sys.percent |
CPU usage. The percentage of time spent executing system code since the last time the statistics were checked. |
Long (int64) |
process.memory.usage |
Current process memory use. |
Integer |
process.percore.cpupercent |
Average CPU usage per core. |
Big Decimal |
process.rss |
Process RSS (bytes) |
Integer |
process.service.usage |
The number of active servicers for the dominant workload — unbound queue servicers or plus queue servicers. |
Integer |
request.completed.count |
Total number of completed requests. |
Integer |
request.active.count |
Total number of active requests. |
Integer |
request.per.sec.1min |
Number of query requests processed per second. 1-minute exponentially weighted moving average. |
Big Decimal |
request.per.sec.5min |
Number of query requests processed per second. 5-minute exponentially weighted moving average. |
Big Decimal |
request.per.sec.15min |
Number of query requests processed per second. 15-minute exponentially weighted moving average. |
Big Decimal |
request.queued.count |
Number of queued requests. |
Integer |
request.quota.used.hwm |
High water mark for request quota use. |
Integer |
request_time.mean |
End-to-end time to process a query. The mean value. |
String (duration) |
request_time.median |
End-to-end time to process a query. The median value. |
String (duration) |
request_time.80percentile |
End-to-end time to process a query. The 80th percentile. |
String (duration) |
request_time.95percentile |
End-to-end time to process a query. The 95th percentile. |
String (duration) |
request_time.99percentile |
End-to-end time to process a query. The 99th percentile. |
String (duration) |
request.prepared.percent |
Percentage of requests that are prepared statements. |
Integer |
servicers.paused.count |
Number of servicers temporarily paused due to memory pressure. (Applies to serverless environments only.) |
Integer |
servicers.paused.total |
Number of times servicers have been temporarily paused. (Applies to serverless environments only.) |
Integer |
temp.hwm |
High water mark for temp space use directly by query. (Doesn't include use by the GSI and FTS clients.) |
Integer |
temp.usage |
Current Query temp space use. (Doesn't include use by the GSI and FTS clients.) |
Integer |
Monitor and Manage Active Requests
The system:active_requests
catalog lists all currently executing active requests or queries.
Get Active Requests
To view active requests, use a SQL++ query.
-
SQL++
To view active requests with SQL++:
SELECT * FROM system:active_requests;
To get the query plan for active requests, include meta().plan
in a SQL++ query.
See Query Profiling.
-
SQL++
To view active requests with SQL++, including the query plan:
SELECT *, meta().plan FROM system:active_requests;
Terminate an Active Request
The DELETE command can be used to terminate an active request, for instance, a non-responding or a long-running query.
-
SQL++
To terminate an active request uuid
with SQL++:
DELETE FROM system:active_requests WHERE requestId = "uuid";
Active Request Details
Getting active requests, as described in Get Active Requests, returns results similar to the following.
[
{
"active_requests": {
"clientContextID": "832adfa0-e9e6-464e-b5e6-b7ec7549d511",
"cpuTime": "111.877µs",
"elapsedTime": "77.631814ms",
"executionTime": "77.517185ms",
"n1qlFeatCtrl": 76,
"node": "127.0.0.1:8091",
"phaseOperators": {
"authorize": 1,
"fetch": 1,
"primaryScan": 1,
"project": 1,
"stream": 1
},
"phaseTimes": {
"authorize": "4.998µs",
"fetch": "69.519µs",
"instantiate": "16.28µs",
"parse": "597.435µs",
"plan": "24.141851ms",
"plan.index.metadata": "24.005473ms",
"plan.keyspace.metadata": "2.022µs",
"primaryScan": "23.496033ms",
"project": "824ns",
"stream": "2.242µs"
},
"queryContext": "default:travel-sample.inventory",
"remoteAddr": "127.0.0.1:37506",
"requestId": "05cc1895-9986-4819-b4d3-8a4311e8f319",
"requestTime": "2024-05-21T13:29:16.864Z",
"scanConsistency": "unbounded",
"state": "running",
"statement": "SELECT * FROM system:active_requests;",
"statementType": "SELECT",
"useCBO": true,
"userAgent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:126.0) Gecko/20100101 Firefox/126.0",
"users": "builtin:Administrator"
}
}
]
This catalog contains the following attributes:
Property | Schema | |
---|---|---|
clientContextID |
The opaque ID or context provided by the client.
Refer to the request-level |
String |
elapsedTime |
The time taken from when the request was acknowledged by the service to when the request was completed. It includes the time taken by the service to schedule the request. |
String (duration) |
errorCount |
Total number of errors encountered while executing the query. |
Integer |
memoryQuota |
The memory quota for the request, in MB. This property is only returned if a memory quota is set for the query. |
Integer |
node |
IP address and port number of the node where the query is executed. |
String |
phaseCounts |
Count of documents processed at selective phases involved in the query execution, such as authorize, index scan, fetch, parse, plan, run, etc. For active requests, this property is dynamic, depending on the documents processed by various phases up to this moment in time. Polling the active requests again may return different values. Example: |
Object |
phaseOperators |
Indicates the numbers of each kind of query operator involved in different phases of the query processing. For instance, a non-covering index path might involve one index scan and one fetch operator. A join would probably involve two or more fetches, one per keyspace. A union select would have twice as many operator counts, one per each branch of the union. Example: |
Object |
phaseTimes |
Cumulative execution times for various phases involved in the query execution, such as authorize, index scan, fetch, parse, plan, run, etc. For active requests, this property is dynamic, depending on the documents processed by various phases up to this moment in time. Polling the active requests again may return different values. Example: |
Object |
remoteAddr |
IP address and port number of the client application, from where the query is received. |
String |
requestId |
Unique request ID internally generated for the query. |
UUID (uuid) |
requestTime |
Timestamp when the query is received. |
Date (date-time) |
resultCount |
Total number of documents returned in the query result. |
Integer |
resultSize |
Total number of bytes returned in the query result. |
Integer |
scanConsistency |
The value of the query setting Scan Consistency used for the query. |
String |
serviceTime |
Total amount of calendar time taken to complete the query. |
String (duration) |
state |
The state of the query execution, such as Note that the To find requests that were successful, use this field in conjunction with the |
String |
statement |
The query statement being executed. |
String |
useCBO |
Whether the cost-based optimizer is enabled for the query. |
Boolean |
usedMemory |
The amount of document memory used to execute the request. This property is only returned if a memory quota is set for the query. |
Integer |
userAgent |
Name of the client application or program that issued the query. |
String |
users |
Username with whose privileges the query is run. |
String |
For query plan field names and meanings, see Query Profiling Details.
Monitor and Manage Prepared Statements
The system:prepareds
catalog provides data about the known prepared statements and their state in a query node’s prepared statement cache.
For each prepared statement, this catalog provides information such as name, statement, query plan, last use time, number of uses, and so on.
A prepared statement is created and stored relative to the current query context. You can create multiple prepared statements with the same name, each stored relative to a different query context. This enables you to run multiple instances of the same application against different datasets.
When there are multiple prepared statements with the same name in different query contexts, the name of the prepared statement in the system:prepareds
catalog includes the associated query context in brackets.
Get Prepared Statements
To get a list of all known prepared statements, use a SQL++ query.
-
SQL++
To get a list of all known prepared statements with a SQL++ query:
SELECT * FROM system:prepareds;
To get information about a specific prepared statement, use a SQL++ query.
-
SQL++
To get information about a specific prepared statement example1
with a SQL++ query:
SELECT * FROM system:prepareds WHERE name = "example1";
To get the query plan for prepared statements, include meta().plan
in a SQL++ query.
See Query Profiling.
-
SQL++
To view prepared statements with SQL++, including the query plan:
SELECT *, meta().plan FROM system:prepareds;
Delete Prepared Statements
To delete a specific prepared statement, use a SQL++ query.
-
SQL++
To delete a prepared statement p1
with a SQL++ query:
DELETE FROM system:prepareds WHERE name = "p1";
To delete all the known prepared statements, use a SQL++ query.
-
SQL++
To delete all known prepared statements:
DELETE FROM system:prepareds;
Prepared Statement Details
To try the examples in this section, first create a couple of prepared statements.
For this example, unset the query context. For more information, see Query Context.
PREPARE p1 AS SELECT * FROM `travel-sample`.inventory.airline WHERE iata = "U2";
For this example, set the query context to the inventory
scope in the travel sample dataset.
For more information, see Query Context.
PREPARE p1 AS SELECT * FROM airline WHERE iata = "U2";
Getting prepared statements, as described in Get Prepared Statements, returns results similar to the following.
{
"requestID": "d976e59a-d74e-4350-b0df-fa137099d594",
"signature": {
"*": "*",
"plan": "json"
},
"results": [
{
"prepareds": {
"encoded_plan": "H4sIAAAAAAAA/6RTUW/TPBT9K9H5XrbJ30QBMcmIhzJ1AjG0qh3wwKbEJLedmWt71061UIXfjpxkndYhENpbYt97z7nn+GxAtnQVVbk3ykICAgtSsWY6djayMwHy6JWAthXdjr3+TBy0s5Avh7N5qewHaoJXJQXIDSpaqNpEGVmtyfwf1MobOtR2TTY6bg6VZqMtQS6UCdQKWLUiSPgR+u9uFOTdIAg4T6yi4zT+v/sfjOt45Vj/IAh41mttaNmTONUhQn7d4FzxkuL9tL/SEpiyXkMepQ/nA+Sz9rIV+FleaVPtMpjTTU22TG19AZPtcP+5aMp6pbhJcr6AwLe6vO54P+CLQfR+n3zLPh/Y576fcleXe3bfqYydYxsMt/k1NZCR66T+9eAdJO4l+L0NoXQ+nWxhIVAHbZeQWAaNVjxc6YRiefWnXZ6EvYs2VayMIYMneXWiTSSGQOlspXvhsLdXDPyKw0KrqIr97E12gU/PL7D/iMh7q6NWZtpLDwGmUJuYR+JV6ADp1qfCQGaRVouKBzsu28s2vbYd4pFJrZDuBFJOtyE8Go0EbmriJqWVbmOfYKab86aTaz45nRyfJxC9tF2skyoHkDhAKzC0TGeT6Xg2yfwoG8+zvic7yE5mZx+z4oFpxePEZF/eTWaTLMmyFeV19zLo+O3ZsNivAAAA//+q+jhuaAQAAA==",
"featuresControl": 76,
"indexApiVersion": 4,
"indexScanKeyspaces": {
"default:travel-sample.inventory.airline": false
},
"name": "p1", (1)
"namespace": "default",
"node": "127.0.0.1:8091",
"statement": "PREPARE p1 AS SELECT * FROM `travel-sample`.inventory.airline WHERE iata = \"U2\";",
"uses": 0
}
},
{
"prepareds": {
"encoded_plan": "H4sIAAAAAAAA/6STT28TMRDFv8rqcWkrExFAVDLiEKpUIIoaJQUOtNqY3Ulq6tju2Bt1iZbPjry7TWmKQKg3/xnPvPk9zwZkC1dSmXujLCQgsCAVK6YjZyM7EyAPXwloW9LNyOvPxEE7C/myP5sVyn6gOnhVUIDcoKSFqkyUkdWazNOgVt7QQNs12ei4HijNRluCXCgTqBGwakWQ8EN06zYV5G0iCDhPrKLjlP7J3QajKl461j8IAp71WhtadiJOdIiQXzc4U7ykeJftn7IEJqzXkIdp4XyAfNZcNAI/i0ttyl0FM7quyBbpWRfAZNu6/x00Yb1SXCecLyDwrSquWt339KKH3vWTb9Xnvfrcd1lu43LP7jsVsXVsg/42v6IaMnKV6F/13kHiDsGfbQiF8+lkWxYCVdB2CYll0GjE/ZaOKRaXf+vlUbV3q00UK2PI4FFeHWsTiSFQOFvqDhz29ua9vvlgrlVU8/3sTXaOT8/Psf9AyHuro1Zm0qGHAFOoTMwj8Sq0BenGp8BAZpFai4p7Oy6aiyb9th3hkUmtkO4E0pxuh/BwOBS4rojrNK108wDy4HevmK7P6pbibHwyPjpLtfXSttOeYB1A4gCNQJ9pMh1PRtNx5ofZaJZ1b7KD7Hh6+jHreWRf3o2n4ywx2RJ53X4LOnp72nf1KwAA////9+bsZQQAAA==",
"featuresControl": 76,
"indexApiVersion": 4,
"indexScanKeyspaces": {
"default:travel-sample.inventory.airline": false
},
"name": "p1(travel-sample.inventory)", (2)
"namespace": "default",
"node": "127.0.0.1:8091",
"statement": "PREPARE p1 AS SELECT * FROM airline WHERE iata = \"U2\";",
"uses": 0
}
}
],
"status": "success",
"metrics": {
"elapsedTime": "25.323496ms",
"executionTime": "25.173646ms",
"resultCount": 2,
"resultSize": 7891,
"serviceLoad": 12
}
}
In this example, the names of the prepared statements are identical, but they are associated with different query contexts.
1 | The name of the prepared statement for the default query context |
2 | The name of the prepared statement showing the associated query context |
This catalog contains the following attributes:
Property | Schema | |
---|---|---|
encoded_plan |
The full prepared statement in encoded format. |
String |
featureControls |
This property is provided for technical support only. It is only returned when retrieving a specific prepared statement, not when retrieving all prepared statements. |
Integer |
indexApiVersion |
This property is provided for technical support only. It is only returned when retrieving a specific prepared statement, not when retrieving all prepared statements. |
Integer |
name |
The name of the prepared statement. This may be a UUID that was assigned automatically, or a name that was user-specified when the statement was created. |
String |
namespace |
The namespace in which the prepared statement is stored.
Currently, only the |
String |
node |
The node on which the prepared statement is stored. |
String |
statement |
The text of the query. |
String |
uses |
The count of times the prepared statement has been executed. |
Integer |
avgElapsedTime |
The mean time taken from when the request to execute the prepared statement was acknowledged by the service, to when the request was completed. It includes the time taken by the service to schedule the request. This property is only returned when the prepared statement has been executed. It is only returned when retrieving a specific prepared statement, not when retrieving all prepared statements. |
String (duration) |
avgServiceTime |
The mean amount of calendar time taken to complete the execution of the prepared statement. This property is only returned when the prepared statement has been executed. It is only returned when retrieving a specific prepared statement, not when retrieving all prepared statements. |
String (duration) |
lastUse |
Date and time of last use. This property is only returned when the prepared statement has been executed. |
Date (date-time) |
maxElapsedTime |
The maximum time taken from when the request to execute the prepared statement was acknowledged by the service, to when the request was completed. It includes the time taken by the service to schedule the request. This property is only returned when the prepared statement has been executed. It is only returned when retrieving a specific prepared statement, not when retrieving all prepared statements. |
String (duration) |
maxServiceTime |
The maximum amount of calendar time taken to complete the execution of the prepared statement. This property is only returned when the prepared statement has been executed. It is only returned when retrieving a specific prepared statement, not when retrieving all prepared statements. |
String (duration) |
minElapsedTime |
The minimum time taken from when the request to execute the prepared statement was acknowledged by the service, to when the request was completed. It includes the time taken by the service to schedule the request. This property is only returned when the prepared statement has been executed. It is only returned when retrieving a specific prepared statement, not when retrieving all prepared statements. |
String (duration) |
minServiceTime |
The minimum amount of calendar time taken to complete the execution of the prepared statement. This property is only returned when the prepared statement has been executed. It is only returned when retrieving a specific prepared statement, not when retrieving all prepared statements. |
String (duration) |
For query plan field names and meanings, see Query Profiling Details.
Monitor and Manage Completed Requests
By default, the system:completed_requests
catalog maintains a list of the most recent completed requests that have run longer than a predefined threshold of time.
(You can also log completed requests that meet other conditions that you define.)
For each completed request, this catalog maintains information such as requestId, statement text, prepared name (if prepared statement), request time, service time, and so on. This information provides a general insight into the health and performance of the query node and the cluster.
Get Completed Requests
To get a list of all logged completed requests, use a SQL++ query.
-
SQL++
To get a list of all logged completed requests using SQL++:
SELECT * FROM system:completed_requests;
Note that the completed
state means that the request was started and completed by the Query service, but it does not mean that it was necessarily successful.
The request could have been successful, or completed with errors.
To find requests that completed successfully, search for completed requests whose state
is completed
and whose errorCount
field has the value 0
.
-
SQL++
To get a list of all logged completed requests, including only successful requests:
SELECT * FROM system:completed_requests
WHERE state = "completed" AND errorCount = 0;
To get the query plan for completed requests, include meta().plan
in a SQL++ query.
See Query Profiling.
-
SQL++
To view completed requests with SQL++, including the query plan:
SELECT *, meta().plan FROM system:completed_requests;
Purge the Completed Requests
To purge a specific completed request, use a SQL++ query.
-
SQL++
To purge a completed request uuid
with SQL++:
DELETE FROM system:completed_requests WHERE requestId = "uuid";
To purge completed requests for a given time period, use a SQL++ query.
-
SQL++
To purge the completed requests for a given time period:
DELETE FROM system:completed_requests WHERE requestTime LIKE "2015-09-09%";
Completed Request Details
To try the examples in this section, first run a query which takes at least 1000ms (the default value of the completed-threshold
query setting) to get registered in the system:completed_requests
keyspace.
For this example, set the query context to the inventory
scope in the travel sample dataset.
For more information, see Query Context.
SELECT * FROM route ORDER BY sourceairport LIMIT 5;
Getting completed requests, as described in Get Completed Requests, returns results similar to the following.
[
// ...
{
"completed_requests": {
"clientContextID": "a19a61ab-cd9e-46c9-be71-92623ff85741",
"cpuTime": "912.408423ms",
"elapsedTime": "3.762926948s",
"errorCount": 0,
"errors": [],
"n1qlFeatCtrl": 76,
"node": "127.0.0.1:8091",
"phaseCounts": {
"fetch": 24023,
"primaryScan": 24023,
"primaryScan.GSI": 24023,
"sort": 24028
},
"phaseOperators": {
"authorize": 1,
"fetch": 1,
"primaryScan": 1,
"primaryScan.GSI": 1,
"project": 1,
"sort": 2,
"stream": 1
},
"phaseTimes": {
"authorize": "15.111µs",
"fetch": "3.641125449s",
"instantiate": "332.963µs",
"parse": "1.04015ms",
"plan": "602.878µs",
"plan.index.metadata": "25.849µs",
"plan.keyspace.metadata": "11.586µs",
"primaryScan": "101.118572ms",
"primaryScan.GSI": "101.118572ms",
"project": "33.273783ms",
"run": "3.760767643s",
"sort": "666.364325ms",
"stream": "1.617688ms"
},
"queryContext": "default:travel-sample.inventory",
"remoteAddr": "127.0.0.1:37684",
"requestId": "e170bf67-d364-4ed7-9698-784bbb779d18",
"requestTime": "2024-05-21T14:31:46.882Z",
"resultCount": 5,
"resultSize": 17714,
"scanConsistency": "unbounded",
"serviceTime": "3.762768429s",
"state": "completed",
"statement": "SELECT * FROM route ORDER BY sourceairport LIMIT 5;",
"statementType": "SELECT",
"useCBO": true,
"userAgent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:126.0) Gecko/20100101 Firefox/126.0",
"users": "builtin:Administrator",
"~qualifier": "threshold"
}
}
]
For field names and meanings, see Active Request Details.
For query plan field names and meanings, see Query Profiling Details.
Query Profiling
Query profiling enables you to obtain more detailed monitoring information and finer execution timings for any query. You can set query profiling to the following levels:
-
off
— query profiling is disabled. -
phases
— query profiling is enabled, including information about the phases of query execution. -
timings
— query profiling is enabled, including information about the phases of query execution, and detailed timing information.
You can set query profiling:
-
At the request level, for individual queries.
For more information about Query settings and parameters, see Configure Queries.
Enable Query Profiling for a Request
To activate profiling at the request level, you can:
-
Specify the
profile
setting using the cbq command line tool.
-
SQL++
To set query settings using the cbq shell, use the \SET
command.
The following statement sets the profiling to phases:
\set -profile "phases";
SELECT * FROM `travel-sample`.inventory.airline LIMIT 1;
The following statement sets the profiling to timings:
\set -profile "timings";
SELECT * FROM `travel-sample`.inventory.airline LIMIT 1;
The Query tab automatically enables Query profiling, with detailed timing information. To disable or enable Query profiling with the Query tab, specify the Collect query timings option using the Query Settings.
Query Profiling Details
You can access the profiling information:
-
In the query responses.
-
In the system catalogs.
When a query executes a user-defined function, profiling information is available for the SQL++ queries within the user-defined function as well.
Profiling Details in Query Responses
When profiling is enabled:
-
If you are using the cbq shell, query profiling information is returned with the query results.
-
If you are using the Query tab, query profiling information is not returned with the query results.
If you are using
the cbq shell, the following statistics are returned when profile
is set to phases
:
{
"requestID": "06d6c1c2-1a8a-4989-a856-7314f9eddee5",
"signature": {
"*": "*"
},
"results": [
{
"airline": {
"callsign": "MILE-AIR",
"country": "United States",
"iata": "Q5",
"icao": "MLA",
"id": 10,
"name": "40-Mile Air",
"type": "airline"
}
}
],
"status": "success",
"metrics": {
"elapsedTime": "12.77927ms",
"executionTime": "12.570648ms",
"resultCount": 1,
"resultSize": 254,
"serviceLoad": 12
},
"profile": {
"phaseTimes": {
"authorize": "19.629µs",
"fetch": "401.997µs",
"instantiate": "147.686µs",
"parse": "4.545234ms",
"plan": "409.364µs",
"primaryScan": "6.103775ms",
"run": "6.699056ms"
},
"phaseCounts": {
"fetch": 1,
"primaryScan": 1
},
"phaseOperators": {
"authorize": 1,
"fetch": 1,
"primaryScan": 1
},
"requestTime": "2021-04-30T18:37:56.394Z",
"servicingHost": "127.0.0.1:8091"
}
}
If you are using
the cbq shell, the following statistics are returned when profile
is set to timings
:
{
"requestID": "268a1240-6864-43a2-af13-ccb8d1e50abf",
"signature": {
"*": "*"
},
"results": [
{
"airline": {
"callsign": "MILE-AIR",
"country": "United States",
"iata": "Q5",
"icao": "MLA",
"id": 10,
"name": "40-Mile Air",
"type": "airline"
}
}
],
"status": "success",
"metrics": {
"elapsedTime": "2.915245ms",
"executionTime": "2.755355ms",
"resultCount": 1,
"resultSize": 254,
"serviceLoad": 12
},
"profile": {
"phaseTimes": {
"authorize": "18.096µs",
"fetch": "388.122µs",
"instantiate": "31.702µs",
"parse": "646.157µs",
"plan": "120.427µs",
"primaryScan": "1.402918ms",
"run": "1.936852ms"
},
"phaseCounts": {
"fetch": 1,
"primaryScan": 1
},
"phaseOperators": {
"authorize": 1,
"fetch": 1,
"primaryScan": 1
},
"requestTime": "2021-04-30T18:40:13.239Z",
"servicingHost": "127.0.0.1:8091",
"executionTimings": {
"#operator": "Authorize",
"#stats": {
"#phaseSwitches": 4,
"execTime": "1.084µs",
"servTime": "17.012µs"
},
"privileges": {
"List": [
{
"Target": "default:travel-sample.inventory.airline",
"Priv": 7,
"Props": 0
}
]
},
"~child": {
"#operator": "Sequence",
"#stats": {
"#phaseSwitches": 1,
"execTime": "2.474µs"
},
"~children": [
{
"#operator": "PrimaryScan3",
"#stats": {
"#itemsOut": 1,
"#phaseSwitches": 7,
"execTime": "18.584µs",
"kernTime": "8.869µs",
"servTime": "1.384334ms"
},
"bucket": "travel-sample",
"index": "def_inventory_airline_primary",
"index_projection": {
"primary_key": true
},
"keyspace": "airline",
"limit": "1",
"namespace": "default",
"scope": "inventory",
"using": "gsi"
},
{
"#operator": "Fetch",
"#stats": {
"#itemsIn": 1,
"#itemsOut": 1,
"#phaseSwitches": 10,
"execTime": "25.64µs",
"kernTime": "1.427752ms",
"servTime": "362.482µs"
},
"bucket": "travel-sample",
"keyspace": "airline",
"namespace": "default",
"scope": "inventory"
},
{
"#operator": "InitialProject",
"#stats": {
"#itemsIn": 1,
"#itemsOut": 1,
"#phaseSwitches": 9,
"execTime": "6.006µs",
"kernTime": "1.825917ms"
},
"result_terms": [
{
"expr": "self",
"star": true
}
]
},
{
"#operator": "Limit",
"#stats": {
"#itemsIn": 1,
"#itemsOut": 1,
"#phaseSwitches": 4,
"execTime": "2.409µs",
"kernTime": "2.094µs"
},
"expr": "1"
},
{
"#operator": "Stream",
"#stats": {
"#itemsIn": 1,
"#itemsOut": 1,
"#phaseSwitches": 6,
"execTime": "46.964µs",
"kernTime": "1.844828ms"
}
}
]
},
"~versions": [
"7.0.0-N1QL",
"7.0.0-4960-enterprise"
]
}
}
}
The profile
object contains the following attributes:
Property | Schema | |
---|---|---|
requestTime |
Timestamp when the query was received. |
Date (date-time) |
servicingHost |
IP address and port number of the node where the query was executed. |
String |
phaseCounts |
Count of documents processed at selective phases involved in the query execution, such as authorize, index scan, fetch, parse, plan, run, etc. Example: |
Object |
phaseOperators |
Indicates the numbers of each kind of query operator involved in different phases of the query processing. For instance, a non-covering index path might involve one index scan and one fetch operator. A join would probably involve two or more fetches, one per keyspace. A union select would have twice as many operator counts, one per each branch of the union. This is in essence the count of all the operators in the Example: |
Object |
phaseTimes |
Cumulative execution times for various phases involved in the query execution, such as authorize, index scan, fetch, parse, plan, run, etc. Example: |
Object |
executionTimings |
Present only if The execution details for various phases involved in the query execution, such as kernel and service execution times, number of documents processed at each query operator in each phase, and number of phase switches. |
Execution Timings
Property | Schema | |
---|---|---|
#operator |
Name of the operator. Example: |
String |
#stats |
Statistics collected for the operator. |
|
~child |
Further nested operators, each with their own execution timings. |
Object |
Statistics
Property | Schema | |
---|---|---|
#itemsIn |
Number of input documents to the operator. Example: |
Integer (int32) |
#itemsOut |
Number of output documents after the operator processing. Example: |
Integer (int32) |
#phaseSwitches |
Number of switches between executing, waiting for services, or waiting for the goroutine scheduler. Example: |
Integer (int32) |
execTime |
Time spent executing the operator code inside SQL++ query engine. Example: |
String (duration) |
kernTime |
Time spent waiting to be scheduled for CPU time. Example: |
String (duration) |
servTime |
Time spent waiting for another service, such as index or data. For index scan, it is time spent waiting for GSI/indexer. For fetch, it is time spent waiting on the KV store. Example: |
String (duration) |
The
|
Profiling Details in System Catalogs
The system:active_requests and system:completed_requests system catalogs always return profiling information regarding query phases: that is, phase times, phase counts, and phase operators.
The system:active_requests, system:completed_requests, and system:prepareds system catalogs also support the meta().plan
virtual attribute.
This captures the whole query plan, and includes profiling information regarding execution timings.
To get execution timing information from these system catalogs, you must explicitly specify meta().plan
in the projection list for the SELECT query.
Within these system catalogs, not all statements have a meta().plan
attribute.
-
With system:active_requests and system:completed_requests, the
meta().plan
attribute is only available for statements that you run when profile is set totimings
. -
With system:prepareds, the
meta().plan
attribute is available for all statements.
When request profiling is set to
|
Getting the plan for a statement that you ran when the profile was set to timings
returns results similar to the following.
[
{
// ...
"plan": {
"#operator": "Authorize",
"#stats": {
"#phaseSwitches": 4,
"execTime": "1.725µs",
"servTime": "21.312µs"
},
"privileges": {
"List": [
{
"Priv": 7,
"Props": 0,
"Target": "default:travel-sample.inventory.route"
}
]
},
"~child": {
"#operator": "Sequence",
"#stats": {
"#phaseSwitches": 2,
"execTime": "1.499µs"
},
"~children": [
{
"#operator": "PrimaryScan3",
"#stats": {
"#heartbeatYields": 6,
"#itemsOut": 24024,
"#phaseSwitches": 96099,
"execTime": "84.366121ms",
"kernTime": "3.021901421s",
"servTime": "69.320752ms"
},
"bucket": "travel-sample",
"index": "def_inventory_route_primary",
"index_projection": {
"primary_key": true
},
"keyspace": "route",
"namespace": "default",
"scope": "inventory",
"using": "gsi"
},
{
"#operator": "Fetch",
"#stats": {
"#heartbeatYields": 7258,
"#itemsIn": 24024,
"#itemsOut": 24024,
"#phaseSwitches": 99104,
"execTime": "70.34694ms",
"kernTime": "142.630196ms",
"servTime": "3.021959695s"
},
"bucket": "travel-sample",
"keyspace": "route",
"namespace": "default",
"scope": "inventory"
},
{
"#operator": "InitialProject",
"#stats": {
"#itemsIn": 24024,
"#itemsOut": 24024,
"#phaseSwitches": 96100,
"execTime": "15.331951ms",
"kernTime": "3.219612458s"
},
"result_terms": [
{
"expr": "self",
"star": true
}
]
},
{
"#operator": "Order",
"#stats": {
"#itemsIn": 24024,
"#itemsOut": 24024,
"#phaseSwitches": 72078,
"execTime": "147.889352ms",
"kernTime": "3.229055752s"
},
"sort_terms": [
{
"expr": "(`route`.`sourceairport`)"
}
]
},
{
"#operator": "Stream",
"#stats": {
"#itemsIn": 24024,
"#itemsOut": 24024,
"#phaseSwitches": 24025,
"execTime": "11.851634134s"
}
}
]
},
"~versions": [
"7.0.0-N1QL",
"7.0.0-4960-enterprise"
]
}
}
]
For field names and meanings, see Execution Timings.
Query Profiling Summary
The following table summarizes Query profiling behavior.
Profile is … | Query returns … | Catalog includes … | ||||
---|---|---|---|---|---|---|
Query |
cbq |
Active |
Completed |
Prepared |
||
|
— |
— |
phases |
phases |
timings |
|
|
— |
phases |
phases |
phases |
timings |
|
|
— |
phases |
phases |
phases |
timings |
Related Links
-
Refer to Getting System Information for more information on the system namespace.