Hi,
Failing to understand performance output (v6.0.2).
Basic Scenario:
- 1M documents, just KEY + Value in one bucket
- 12 cores machine (with HT 24vCPU): DATA, QUERY, INDEX (256GB ram, 100% resident)
Config
One Primary Index as it will be a full scan.
(adding an index in the value doesn’t change the time result, as expected)
Query:
update MyTestBucket
set myValue=50
Results
Parallelism 1: 60s
Parallelism 4: 40s
Parallelism 24: 20s
Questions
Cannot understand why KernTime for PrimaryScan is 41s. What is it doing? and how come Fetch has another 30s KernTime. How this KernTime is measure? I cannot see how the sum up off all these times is 5 times bigger than the total time of the query.
I am clueless why such as simple query takes that massive amount of time. It is only 1M simple documents
Plan
{
"#operator": "Sequence",
"#stats": {
"#phaseSwitches": 1,
"execTime": "4.178µs"
},
"~children": [
{
"#operator": "Authorize",
"#stats": {
"#phaseSwitches": 3,
"execTime": "11.988µs",
"servTime": "967.205µs"
},
"privileges": {
"List": [
{
"Target": "default:MyTestBucket",
"Priv": 8
}
]
},
"~child": {
"#operator": "Sequence",
"#stats": {
"#phaseSwitches": 1,
"execTime": "8.013µs"
},
"~children": [
{
"#operator": "PrimaryScan3",
"#stats": {
"#itemsOut": 422917,
"#phaseSwitches": 1691671,
"execTime": "1.01515339s",
"kernTime": "41.834858434s",
"servTime": "293.844824ms"
},
"index": "MyTestBucket-idx",
"index_projection": {
"primary_key": true
},
"keyspace": "MyTestBucket",
"namespace": "default",
"using": "gsi",
"#time_normal": "00:01.3089",
"#time_absolute": 1.308998214
},
{
"#operator": "Sequence",
"#stats": {
"#phaseSwitches": 1,
"execTime": "19.388µs"
},
"~children": [
{
"#operator": "Fetch",
"#stats": {
"#itemsIn": 422917,
"#itemsOut": 422917,
"#phaseSwitches": 1744537,
"execTime": "1.451948471s",
"kernTime": "30.536174622s",
"servTime": "11.209811943s"
},
"keyspace": "MyTestBucket",
"namespace": "default",
"#time_normal": "00:12.6617",
"#time_absolute": 12.661760414
},
{
"#operator": "Clone",
"#stats": {
"#itemsIn": 422917,
"#itemsOut": 422917,
"#phaseSwitches": 1691671,
"execTime": "3.646958513s",
"kernTime": "39.599537304s"
},
"#time_normal": "00:03.6469",
"#time_absolute": 3.646958513
},
{
"#operator": "Set",
"#stats": {
"#itemsIn": 422917,
"#itemsOut": 422917,
"#phaseSwitches": 1691671,
"execTime": "705.135974ms",
"kernTime": "42.58877295s"
},
"set_terms": [
{
"path": "(`MyTestBucket`.`numberOfHits`)",
"value": "50"
}
],
"#time_normal": "00:00.7051",
"#time_absolute": 0.705135974
},
{
"#operator": "SendUpdate",
"#stats": {
"#itemsIn": 422917,
"#itemsOut": 422917,
"#phaseSwitches": 1744537,
"execTime": "1.087421138s",
"kernTime": "310.070779ms",
"servTime": "41.945761193s"
},
"alias": "MyTestBucket",
"keyspace": "MyTestBucket",
"namespace": "default",
"#time_normal": "00:43.0331",
"#time_absolute": 43.033182331000006
}
],
"#time_normal": "00:00.0000",
"#time_absolute": 0.000019388
},
{
"#operator": "Discard",
"#stats": {
"#itemsIn": 422917,
"#phaseSwitches": 845837,
"execTime": "47.909714ms",
"kernTime": "43.295380593s"
},
"#time_normal": "00:00.0479",
"#time_absolute": 0.047909714
}
],
"#time_normal": "00:00.0000",
"#time_absolute": 0.000008013
},
"#time_normal": "00:00.0009",
"#time_absolute": 0.0009791930000000002
},
{
"#operator": "Stream",
"#stats": {
"#phaseSwitches": 3,
"execTime": "4.162µs",
"kernTime": "43.344287065s"
},
"#time_normal": "00:00.0000",
"#time_absolute": 0.000004162
}
],
"~versions": [
"2.0.0-N1QL",
"6.0.2-2413-enterprise"
],
"#time_normal": "00:00.0000",
"#time_absolute": 0.000004178
}