Hi, the documentation states that profile can be turned on by running the below query. It will give the granular details and cost of each phase. I wanted to know if turning on profile is recommended in a production cluster
curl http://localhost:8093/admin/settings -u user:pword
-H ‘Content-Type: application/json’
-d ‘{“profile”: “phases”}’
Thanks
https://docs.couchbase.com/server/current/manage/monitor/monitoring-n1ql-query.html#monitor-profile-details
“timings” one is not recommended because it uses more memory. phases should be fine, once you done you can turn off. @Marco_Greco can confirm.
The issue with profiling is that if a request ends in system:completed_requests, the timings will be stored as well,
This is useful because it allows you to go back and study the plan and the bottleneck for the slow query.
If you keep profile set to timings all the time, then all of your requests in system:completed_requests will store timings, which, as @vsr1 says, uses a lot of memory.
For this reason it’s best that profiles are only collected when needed.
Bear in mind that you can turn on timings in flight - so if you spot a very slow request executing, you can turn on timings and with the /admin/settings endpoint, and collect timings there and then with system:active_requests, or let it run, and collect them in system:completed_requests, and you can then turn off timings.
For phases, there’s not a lot of memory that’s been used, and it’s ok to keep them on.
Noticed that even if I turn on timings, the executionTimings do not get loaded into system:completed_requests. When I run through CBQ, i do see the executionTimings in the output. Am I missing anything?
cbq> select * from `travel-sample` where id like "kair%";
{
"requestID": "c8091ae3-94c7-4b4c-8166-2164b0ac1f25",
"signature": {
"*": "*"
},
"results": [
],
"status": "success",
"metrics": {
"elapsedTime": "6.5421608s",
"executionTime": "6.5411604s",
"resultCount": 0,
"resultSize": 0
},
"profile": {
"phaseTimes": {
"fetch": "6.5096448s",
"filter": "183.173ms",
"plan": "2.0872ms",
"primaryScan": "73.9838ms",
"run": "6.5390732s"
},
"phaseCounts": {
"fetch": 31592,
"primaryScan": 31592
},
"phaseOperators": {
"authorize": 1,
"fetch": 1,
"filter": 1,
"primaryScan": 1
},
"executionTimings": {
"#operator": "Sequence",
"#stats": {
"#phaseSwitches": 1
},
"~children": [
{
"#operator": "Authorize",
"#stats": {
"#phaseSwitches": 3
},
"privileges": {
"List": [
{
"Target": "default:travel-sample",
"Priv": 7
}
]
},
"~child": {
"#operator": "Sequence",
"#stats": {
"#phaseSwitches": 1
},
"~children": [
{
"#operator": "PrimaryScan3",
"#stats": {
"#itemsOut": 31592,
"#phaseSwitches": 126371,
"execTime": "57.0641ms",
"kernTime": "6.3310867s",
"servTime": "16.9197ms"
},
"index": "def_primary",
"index_projection": {
"primary_key": true
},
"keyspace": "travel-sample",
system:completed_requests is a snapshot, meaning that the request information is assembled at the time the request completes.
If timings were on at the time the request completes, then they will be collected, if not they will be omitted.
Further, the timings are shown in the plan meta() field.
example:
$ curl http://localhost:8093/query/service -u Administrator:password -d 'statement=select * from `travel-sample`&pretty=true'
...
"status": "success",
"metrics": {
"elapsedTime": "6.863385199s",
"executionTime": "6.86335077s",
"resultCount": 31591,
"resultSize": 95381286,
"serviceLoad": 2
}
}
$ curl http://localhost:8093/query/service -u Administrator:password -d 'statement=select * from system:completed_requests&pretty=true'
{
"requestID": "ae152c62-bf3d-4893-a452-c54a05744cf5",
"signature": {
"*": "*"
},
"results": [
{
"completed_requests": {
"elapsedTime": "6.863385199s",
"errorCount": 0,
"node": "127.0.0.1:8091",
"phaseCounts": {
"fetch": 31591,
"primaryScan": 31591
},
"phaseOperators": {
"authorize": 1,
"fetch": 1,
"primaryScan": 1
},
"phaseTimes": {
"authorize": "11.553µs",
"fetch": "731.687404ms",
"instantiate": "9.714µs",
"parse": "191.778µs",
"plan": "73.656µs",
"primaryScan": "21.196667ms",
"run": "6.863068102s"
},
"remoteAddr": "127.0.0.1:32818",
"requestId": "75693cc1-b43e-49f4-9975-a560f35c9ced",
"requestTime": "2021-08-27T08:27:33.868+01:00",
"resultCount": 31591,
"resultSize": 95381286,
"scanConsistency": "unbounded",
"serviceTime": "6.86335077s",
"state": "completed",
"statement": "select * from `travel-sample`",
"statementType": "SELECT",
"useCBO": true,
"userAgent": "curl/7.68.0",
"users": "Administrator"
}
}
],
"status": "success",
"metrics": {
"elapsedTime": "16.212821ms",
"executionTime": "16.178185ms",
"resultCount": 1,
"resultSize": 1303,
"serviceLoad": 2
}
}
$ curl http://localhost:8093/query/service -u Administrator:password -d 'statement=select *, meta().plan from system:completed_requests&pretty=true'
{
"requestID": "9bab8b4d-fdee-46bd-be42-ee1c39a33ed6",
"signature": {
"*": "*",
"plan": "json"
},
"results": [
{
"completed_requests": {
"elapsedTime": "6.863385199s",
"errorCount": 0,
"node": "127.0.0.1:8091",
"phaseCounts": {
"fetch": 31591,
"primaryScan": 31591
},
"phaseOperators": {
"authorize": 1,
"fetch": 1,
"primaryScan": 1
},
"phaseTimes": {
"authorize": "11.553µs",
"fetch": "731.687404ms",
"instantiate": "9.714µs",
"parse": "191.778µs",
"plan": "73.656µs",
"primaryScan": "21.196667ms",
"run": "6.863068102s"
},
"remoteAddr": "127.0.0.1:32818",
"requestId": "75693cc1-b43e-49f4-9975-a560f35c9ced",
"requestTime": "2021-08-27T08:27:33.868+01:00",
"resultCount": 31591,
"resultSize": 95381286,
"scanConsistency": "unbounded",
"serviceTime": "6.86335077s",
"state": "completed",
"statement": "select * from `travel-sample`",
"statementType": "SELECT",
"useCBO": true,
"userAgent": "curl/7.68.0",
"users": "Administrator"
}
}
],
"status": "success",
"metrics": {
"elapsedTime": "18.852189ms",
"executionTime": "18.796403ms",
"resultCount": 1,
"resultSize": 1303,
"serviceLoad": 2
}
}
as you can see, no plans are collected, but now
$ curl http://localhost:8093/query/service -u Administrator:password -d 'statement=select * from `travel-sample`&profile=timings&pretty=true'
...
"status": "success",
"metrics": {
"elapsedTime": "7.057874836s",
"executionTime": "7.057770189s",
"resultCount": 31591,
"resultSize": 95381286,
"serviceLoad": 2
},
"profile": {
"phaseTimes": {
"authorize": "29.297µs",
"fetch": "739.588647ms",
"instantiate": "24.718µs",
"parse": "791.978µs",
"plan": "229.219µs",
"primaryScan": "26.358675ms",
"run": "7.056701298s"
},
"phaseCounts": {
"fetch": 31591,
"primaryScan": 31591
},
"phaseOperators": {
"authorize": 1,
"fetch": 1,
"primaryScan": 1
},
"requestTime": "2021-08-27T08:30:50.853+01:00",
"servicingHost": "127.0.0.1:8091",
"executionTimings": {
"#operator": "Authorize",
"#stats": {
"#phaseSwitches": 4,
"execTime": "2.791µs",
"servTime": "26.506µs"
},
"privileges": {
"List": [
{
"Target": "default:travel-sample",
"Priv": 7,
"Props": 0
}
]
},
"~child": {
"#operator": "Sequence",
"#stats": {
"#phaseSwitches": 2,
"execTime": "2.654µs"
},
"~children": [
{
"#operator": "PrimaryScan3",
"#stats": {
"#heartbeatYields": 2,
"#itemsOut": 31591,
"#phaseSwitches": 126367,
"execTime": "14.118455ms",
"kernTime": "6.650319174s",
"servTime": "12.24022ms"
},
"index": "def_primary",
"index_projection": {
"primary_key": true
},
"keyspace": "travel-sample",
"namespace": "default",
"using": "gsi"
},
{
"#operator": "Fetch",
"#stats": {
"#heartbeatYields": 83,
"#itemsIn": 31591,
"#itemsOut": 31591,
"#phaseSwitches": 130318,
"execTime": "52.905834ms",
"kernTime": "6.096674826s",
"servTime": "686.682813ms"
},
"keyspace": "travel-sample",
"namespace": "default"
},
{
"#operator": "InitialProject",
"#stats": {
"#itemsIn": 31591,
"#itemsOut": 31591,
"#phaseSwitches": 94778,
"execTime": "17.682417ms",
"kernTime": "60.609268ms",
"state": "running"
},
"result_terms": [
{
"expr": "self",
"star": true
}
]
},
{
"#operator": "Stream",
"#stats": {
"#itemsIn": 31591,
"#itemsOut": 31591,
"#phaseSwitches": 31592,
"execTime": "6.98255083s"
}
}
]
},
"~versions": [
"7.1.0-N1QL",
"7.1.0-1198-enterprise"
]
}
}
}
$ curl http://localhost:8093/query/service -u Administrator:password -d 'statement=select *, meta().plan from system:completed_requests&pretty=true'
{
"requestID": "5424c46f-a18a-428e-b370-d855474d8119",
"signature": {
"*": "*",
"plan": "json"
},
"results": [
{
"completed_requests": {
"elapsedTime": "7.057874836s",
"errorCount": 0,
"node": "127.0.0.1:8091",
"phaseCounts": {
"fetch": 31591,
"primaryScan": 31591
},
"phaseOperators": {
"authorize": 1,
"fetch": 1,
"primaryScan": 1
},
"phaseTimes": {
"authorize": "29.297µs",
"fetch": "739.588647ms",
"instantiate": "24.718µs",
"parse": "791.978µs",
"plan": "229.219µs",
"primaryScan": "26.358675ms",
"run": "7.056701298s"
},
"remoteAddr": "127.0.0.1:33002",
"requestId": "0dfe47f2-a53f-4b2d-9faa-9046feafcc06",
"requestTime": "2021-08-27T08:30:50.853+01:00",
"resultCount": 31591,
"resultSize": 95381286,
"scanConsistency": "unbounded",
"serviceTime": "7.057770189s",
"state": "completed",
"statement": "select * from `travel-sample`",
"statementType": "SELECT",
"useCBO": true,
"userAgent": "curl/7.68.0",
"users": "Administrator"
},
"plan": {
"#operator": "Authorize",
"#stats": {
"#phaseSwitches": 4,
"execTime": "2.791µs",
"servTime": "26.506µs"
},
"privileges": {
"List": [
{
"Priv": 7,
"Props": 0,
"Target": "default:travel-sample"
}
]
},
"~child": {
"#operator": "Sequence",
"#stats": {
"#phaseSwitches": 2,
"execTime": "2.654µs"
},
"~children": [
{
"#operator": "PrimaryScan3",
"#stats": {
"#heartbeatYields": 2,
"#itemsOut": 31591,
"#phaseSwitches": 126367,
"execTime": "14.118455ms",
"kernTime": "6.650319174s",
"servTime": "12.24022ms"
},
"index": "def_primary",
"index_projection": {
"primary_key": true
},
"keyspace": "travel-sample",
"namespace": "default",
"using": "gsi"
},
{
"#operator": "Fetch",
"#stats": {
"#heartbeatYields": 83,
"#itemsIn": 31591,
"#itemsOut": 31591,
"#phaseSwitches": 130318,
"execTime": "52.905834ms",
"kernTime": "6.096674826s",
"servTime": "686.682813ms"
},
"keyspace": "travel-sample",
"namespace": "default"
},
{
"#operator": "InitialProject",
"#stats": {
"#itemsIn": 31591,
"#itemsOut": 31591,
"#phaseSwitches": 94778,
"execTime": "1m36.787900114s",
"kernTime": "60.609268ms",
"state": "running"
},
"result_terms": [
{
"expr": "self",
"star": true
}
]
},
{
"#operator": "Stream",
"#stats": {
"#itemsIn": 31591,
"#itemsOut": 31591,
"#phaseSwitches": 31592,
"execTime": "6.98255083s"
}
}
]
},
"~versions": [
"7.1.0-N1QL",
"7.1.0-1198-enterprise"
]
}
},
{
"completed_requests": {
"elapsedTime": "6.863385199s",
"errorCount": 0,
"node": "127.0.0.1:8091",
"phaseCounts": {
"fetch": 31591,
"primaryScan": 31591
},
"phaseOperators": {
"authorize": 1,
"fetch": 1,
"primaryScan": 1
},
"phaseTimes": {
"authorize": "11.553µs",
"fetch": "731.687404ms",
"instantiate": "9.714µs",
"parse": "191.778µs",
"plan": "73.656µs",
"primaryScan": "21.196667ms",
"run": "6.863068102s"
},
"remoteAddr": "127.0.0.1:32818",
"requestId": "75693cc1-b43e-49f4-9975-a560f35c9ced",
"requestTime": "2021-08-27T08:27:33.868+01:00",
"resultCount": 31591,
"resultSize": 95381286,
"scanConsistency": "unbounded",
"serviceTime": "6.86335077s",
"state": "completed",
"statement": "select * from `travel-sample`",
"statementType": "SELECT",
"useCBO": true,
"userAgent": "curl/7.68.0",
"users": "Administrator"
}
}
],
"status": "success",
"metrics": {
"elapsedTime": "16.630346ms",
"executionTime": "16.589619ms",
"resultCount": 2,
"resultSize": 5919,
"serviceLoad": 2
}
}
The first request was collected with no timings, the second with timings
Thanks a lot Marco, this explains. I was missing the meta().plan part