fiware-cygnus
fiware-cygnus copied to clipboard
telefonicaid
MongoDB indexes cyg_raw_opt could have worsened in newers versions
Based on the discussion on https://stackoverflow.com/questions/76570277/differences-in-query-logs-when-read-by-sth-comet-caused-by-cygnus-version-upgrad (I'd suggest to read it carefully) the indexes created by Cygnus at MongoDB could have worsened from 2.20.0 to 3.2.0
In 2.20.0:
> db['sth_/'].getIndexes()
[
{
"v" : 2,
"key" : {
"_id" : 1
},
"name" : "_id_"
},
{
"v" : 2,
"key" : {
"entityId" : 1,
"entityType" : 1,
"attrName" : 1,
"recvTime" : 1
},
"name" : "cyg_raw_opt"
},
{
"v" : 2,
"key" : {
"recvTime" : 1
},
"name" : "cyg_raw_exp",
"expireAfterSeconds" : NumberLong(1576800000)
}
]
In 3.2.0:
rs0:PRIMARY> db['sth_/'].getIndexes()
[
{
"v" : 2,
"key" : {
"_id" : 1
},
"name" : "_id_"
},
{
"v" : 2,
"key" : {
"entityId" : 1,
"entityType" : 1,
"attrName" : 1,
"recvTime" : 1
},
"name" : "entityId_1_entityType_1_attrName_1_recvTime_1"
},
{
"v" : 2,
"key" : {
"recvTime" : 1,
"entityId" : 1,
"entityType" : 1,
"attrName" : 1,
"attrType" : 1,
"attrValue" : 1
},
"name" : "cyg_raw_opt"
},
{
"v" : 2,
"key" : {
"recvTime" : 1
},
"name" : "cyg_raw_exp",
"expireAfterSeconds" : NumberLong(1576800000)
}
]
The entityId_1_entityType_1_attrName_1_recvTime_1 was added manually (the same as old cyg_raw_opt).
Based on the discussion on https://stackoverflow.com/questions/76570277/differences-in-query-logs-when-read-by-sth-comet-caused-by-cygnus-version-upgrad
Answer to that question at SOF should be edited when this issue gets addressed (maybe saying the new version in which the fix would be included).
Relevant cygnus configuration, from SOF question:
environment:
- CYGNUS_MONGO_HOSTS=mongo:27017
- CYGNUS_API_PORT=5080
- CYGNUS_MONGO_DATA_MODEL=dm-by-service-path
- CYGNUS_STH_DATA_MODEL=dm-by-service-path
Hi @fgalan ,
I have tried to reproduce the issue. Index creation is reproduced successfully. I could not find planSummary in Mongo logs. I have tried to check the scenario as below:
Prepared the mongo query as per the code https://github.com/telefonicaid/fiware-sth-comet/blob/2.10.0/lib/database/sthDatabase.js#L503 and then get the executionStats of the query.
In case of collection-per-service-path, below mongo query will be executed:
db["sth/testsink"].find({"entityId":"Room1","entityType":"Room","attrName":"temperature"}, {_id: 0,attrType: 1,attrValue: 1,recvTime: 1}).sort({ recvTime: -1 }).explain('executionStats');
winningPlan of above query is using index cyg_raw_opt index. So, it seems that index is correctly used by STH-Comet.
"stage" : "PROJECTION_SIMPLE",
"transformBy" : {
"_id" : 0,
"attrType" : 1,
"attrValue" : 1,
"recvTime" : 1
},
"inputStage" : {
"stage" : "FETCH",
"filter" : {
"$and" : [
{
"attrName" : {
"$eq" : "temperature"
}
},
{
"entityId" : {
"$eq" : "Room1"
}
},
{
"entityType" : {
"$eq" : "Room"
}
}
]
},
"inputStage" : {
"stage" : "IXSCAN",
"keyPattern" : {
"recvTime" : 1,
"entityId" : 1,
"entityType" : 1,
"attrName" : 1,
"attrType" : 1,
"attrValue" : 1
},
"indexName" : "cyg_raw_opt",
"isMultiKey" : false,
"multiKeyPaths" : {
"recvTime" : [ ],
"entityId" : [ ],
"entityType" : [ ],
"attrName" : [ ],
"attrType" : [ ],
"attrValue" : [ ]
},
As per my understanding, index is correctly used. Please confirm my understanding.
@ctc-watanabe as you were the one that raised this issue, could you have a look to @MadhuNEC comment and provide feedback, please? Thanks in advance!
Note PR https://github.com/telefonicaid/fiware-cygnus/pull/2314 has been recently merged.
Not sure if this PR could be related with this issue... please take it into account.
@fgalan Thank you for making contact.
I have investigated on the master branch, but it seems that the problem has not been resolved. As @MadhuNEC says, indexes are used for the FIND process performed by STH-Comet. However, the process that no longer uses the index is the COUNT process that is executed before the FIND process, as shown in the log I described in the SOF.
// Log of STH-Comet query to get data written by Cygnus 2.20.0
{"t":{"$date":"2023-06-28T03:54:01.910+00:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"conn11","msg":"Slow query","attr":{"type":"command","ns":"sth_example.$cmd","command":{"listCollections":1,"filter":{"name":"sth_/"},"cursor":{},"nameOnly":true,"lsid":{"id":{"$uuid":"a7f6f881-1db3-42f0-86b6-c14fc3425419"}},"$db":"sth_example"},"numYields":0,"reslen":166,"locks":{"ParallelBatchWriterMode":{"acquireCount":{"r":1}},"FeatureCompatibilityVersion":{"acquireCount":{"r":1}},"ReplicationStateTransition":{"acquireCount":{"w":1}},"Global":{"acquireCount":{"r":1}},"Database":{"acquireCount":{"r":1}},"Collection":{"acquireCount":{"r":2}},"Mutex":{"acquireCount":{"r":1}}},"protocol":"op_msg","durationMillis":0}}
{"t":{"$date":"2023-06-28T03:54:01.916+00:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"conn11","msg":"Slow query","attr":{"type":"command","ns":"sth_example.sth_/","command":{"count":"sth_/","query":{"entityId":"Car1","entityType":"Car","attrName":"speed"},"skip":0,"limit":0,"$db":"sth_example"},"planSummary":"COUNT_SCAN { entityId: 1, entityType: 1, attrName: 1, recvTime: 1 }","keysExamined":3,"docsExamined":0,"numYields":0,"queryHash":"41C2776D","planCacheKey":"2D54FA2D","reslen":45,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":1}},"ReplicationStateTransition":{"acquireCount":{"w":1}},"Global":{"acquireCount":{"r":1}},"Database":{"acquireCount":{"r":1}},"Collection":{"acquireCount":{"r":1}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"protocol":"op_msg","durationMillis":0}}
{"t":{"$date":"2023-06-28T03:54:01.920+00:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"conn11","msg":"Slow query","attr":{"type":"command","ns":"sth_example.sth_/","command":{"find":"sth_/","filter":{"entityId":"Car1","entityType":"Car","attrName":"speed"},"sort":{"recvTime":-1},"limit":5,"returnKey":false,"showRecordId":false,"lsid":{"id":{"$uuid":"a7f6f881-1db3-42f0-86b6-c14fc3425419"}},"$db":"sth_example"},"planSummary":"IXSCAN { entityId: 1, entityType: 1, attrName: 1, recvTime: 1 }","keysExamined":2,"docsExamined":2,"cursorExhausted":true,"numYields":0,"nreturned":2,"queryHash":"C0A2C615","planCacheKey":"26B66C8B","reslen":380,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":1}},"ReplicationStateTransition":{"acquireCount":{"w":1}},"Global":{"acquireCount":{"r":1}},"Database":{"acquireCount":{"r":1}},"Collection":{"acquireCount":{"r":1}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"protocol":"op_msg","durationMillis":0}}
// Log of STH-Comet query to get data written by Cygnus 3.2.0
{"t":{"$date":"2023-06-28T03:43:44.631+00:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"conn11","msg":"Slow query","attr":{"type":"command","ns":"sth_example.$cmd","command":{"listCollections":1,"filter":{"name":"sth_/"},"cursor":{},"nameOnly":true,"lsid":{"id":{"$uuid":"8dde283d-302e-4374-aa83-a3c78a19080c"}},"$db":"sth_example"},"numYields":0,"reslen":166,"locks":{"ParallelBatchWriterMode":{"acquireCount":{"r":1}},"FeatureCompatibilityVersion":{"acquireCount":{"r":1}},"ReplicationStateTransition":{"acquireCount":{"w":1}},"Global":{"acquireCount":{"r":1}},"Database":{"acquireCount":{"r":1}},"Collection":{"acquireCount":{"r":2}},"Mutex":{"acquireCount":{"r":1}}},"protocol":"op_msg","durationMillis":0}}
{"t":{"$date":"2023-06-28T03:43:44.634+00:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"conn11","msg":"Slow query","attr":{"type":"command","ns":"sth_example.sth_/","command":{"count":"sth_/","query":{"entityId":"Car1","entityType":"Car","attrName":"speed"},"skip":0,"limit":0,"$db":"sth_example"},"planSummary":"COLLSCAN","keysExamined":0,"docsExamined":2,"numYields":0,"queryHash":"41C2776D","planCacheKey":"2D54FA2D","reslen":45,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":1}},"ReplicationStateTransition":{"acquireCount":{"w":1}},"Global":{"acquireCount":{"r":1}},"Database":{"acquireCount":{"r":1}},"Collection":{"acquireCount":{"r":1}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"protocol":"op_msg","durationMillis":0}}
{"t":{"$date":"2023-06-28T03:43:44.636+00:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"conn11","msg":"Slow query","attr":{"type":"command","ns":"sth_example.sth_/","command":{"find":"sth_/","filter":{"entityId":"Car1","entityType":"Car","attrName":"speed"},"sort":{"recvTime":-1},"limit":5,"returnKey":false,"showRecordId":false,"lsid":{"id":{"$uuid":"8dde283d-302e-4374-aa83-a3c78a19080c"}},"$db":"sth_example"},"planSummary":"IXSCAN { recvTime: 1, entityId: 1, entityType: 1, attrName: 1, attrType: 1, attrValue: 1 }","keysExamined":2,"docsExamined":2,"cursorExhausted":true,"numYields":0,"nreturned":2,"queryHash":"C0A2C615","planCacheKey":"26B66C8B","reslen":380,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":1}},"ReplicationStateTransition":{"acquireCount":{"w":1}},"Global":{"acquireCount":{"r":1}},"Database":{"acquireCount":{"r":1}},"Collection":{"acquireCount":{"r":1}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"protocol":"op_msg","durationMillis":0}}
Probably, it is the process of the following code in STH-Comet. https://github.com/telefonicaid/fiware-sth-comet/blob/9ece83786b6ab7785416be29c3a89a551364a151/lib/database/sthDatabase.js#L510-L523
I checked the COUNT process with the following command, and it is still COUNT_SCAN in Cygnus 2.20.0.
> db.runCommand({explain: {count: 'sth_/',query: {"entityId":"Car1","entityType":"Car","attrName":"speed"}}})
{
"queryPlanner" : {
"plannerVersion" : 1,
"namespace" : "sth_example.sth_/",
"indexFilterSet" : false,
"parsedQuery" : {
"$and" : [
{
"attrName" : {
"$eq" : "speed"
}
},
{
"entityId" : {
"$eq" : "Car1"
}
},
{
"entityType" : {
"$eq" : "Car"
}
}
]
},
"winningPlan" : {
"stage" : "COUNT",
"inputStage" : {
"stage" : "COUNT_SCAN",
"keyPattern" : {
"entityId" : 1,
"entityType" : 1,
"attrName" : 1,
"recvTime" : 1
},
"indexName" : "cyg_raw_opt",
"isMultiKey" : false,
"multiKeyPaths" : {
"entityId" : [ ],
"entityType" : [ ],
"attrName" : [ ],
"recvTime" : [ ]
},
"isUnique" : false,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 2,
"indexBounds" : {
However, in Cygnus 3.2.0 and master branch, it is COLLSCAN as follows.
> db.runCommand({explain: {count: 'sth_/',query: {"entityId":"Car1","entityType":"Car","attrName":"speed"}}})
{
"queryPlanner" : {
"plannerVersion" : 1,
"namespace" : "sth_example.sth_/",
"indexFilterSet" : false,
"parsedQuery" : {
"$and" : [
{
"attrName" : {
"$eq" : "speed"
}
},
{
"entityId" : {
"$eq" : "Car1"
}
},
{
"entityType" : {
"$eq" : "Car"
}
}
]
},
"winningPlan" : {
"stage" : "COUNT",
"inputStage" : {
"stage" : "COLLSCAN",
"filter" : {
"$and" : [
{
"attrName" : {
"$eq" : "speed"
}
},
{
"entityId" : {
"$eq" : "Car1"
}
},
{
"entityType" : {
"$eq" : "Car"
}
}
]
},
"direction" : "forward"
}
},
After this PR https://github.com/telefonicaid/fiware-cygnus/pull/2205/ indexed are created having into account DataModel (DM) type. Which DM is involve in this case ?
Then index for sth collection involves the following keys:
- recvTime, entityId, entityType, attrName, attrType, attrValue for cyg_raw_opt index
- entityId, entityType, attrName, resolution, origin for cyg_agg_exp index
Moreover, after PR https://github.com/telefonicaid/fiware-cygnus/pull/2314 indexes when expirates are recreated even when conflict due to datamodel has changed.