'Problems with same query in mongoid rails db but different parameters
I’m using mongoid gem ’mongoid’, ’~> 7.2.4’ (mongoDB 3.6) with rails (5) and I have a database with customer collections and bills with this relation:
class Bill
...
belongs_to :customer, index: true
...
end
class Customer
....
has_many :bills
...
end
then in a pry console I test with two clients:
[55] pry(main)> c_slow.class
=> Customer
[58] pry(main)> c_slow.bills.count
MONGODB | pro-app-mongodb-05:27017 req:1030 conn:1:1 | db_api_production.aggregate | STARTED | {"aggregate"=>"bills", "pipeline"=>[{"$match"=>{"deleted_at"=>nil, "customer_id"=>BSON::ObjectId('60c76b9e21225c002044f6c5')}}, {"$group"=>{"_id"=>1, "n"=>{"$sum"=>1}}}], "cursor"=>{}, "$db"=>"db_api_production", "$clusterTime"=>{"clusterTime"=>#...
MONGODB | pro-app-mongodb-05:27017 req:1030 | db_api_production.aggregate | SUCCEEDED | 0.008s
=> 523
[59] pry(main)> c_fast.bills.count
MONGODB | pro-app-mongodb-05:27017 req:1031 conn:1:1 | db_api_production.aggregate | STARTED | {"aggregate"=>"bills", "pipeline"=>[{"$match"=>{"deleted_at"=>nil, "customer_id"=>BSON::ObjectId('571636f44a506256d6000003')}}, {"$group"=>{"_id"=>1, "n"=>{"$sum"=>1}}}], "cursor"=>{}, "$db"=>"db_api_production", "$clusterTime"=>{"clusterTime"=>#...
MONGODB | pro-app-mongodb-05:27017 req:1031 | db_api_production.aggregate | SUCCEEDED | 0.135s
=> 35913
until this moment it seems correct but when I execute this query:
[60] pry(main)> c_slow.bills.excludes(_id: BSON::ObjectId('62753df4a54d7584e56ea829')).order(reference: :desc).limit(1000).pluck(:reference, :_id)
MONGODB | pro-app-mongodb-05:27017 req:1083 conn:1:1 | db_api_production.find | STARTED | {"find"=>"bills", "filter"=>{"deleted_at"=>nil, "customer_id"=>BSON::ObjectId('60c76b9e21225c002044f6c5'), "_id"=>{"$ne"=>BSON::ObjectId('62753df4a54d7584e56ea829')}}, "limit"=>1000, "sort"=>{"reference"=>-1}, "projection"=>{"reference"=>1, "_id"=>1...
MONGODB | pro-app-mongodb-05:27017 req:1083 | db_api_production.find | SUCCEEDED | 10.075s
MONGODB | pro-app-mongodb-05:27017 req:1087 conn:1:1 | db_api_production.getMore | STARTED | {"getMore"=>#<BSON::Int64:0x0000558bcd7ba5f8 @value=165481790189>, "collection"=>"bills", "$db"=>"db_api_production", "$clusterTime"=>{"clusterTime"=>#<BSON::Timestamp:0x0000558bcd7a4b90 @seconds=1652511506, @increment=1>, "signature"=>{"hash"=><...
MONGODB | pro-app-mongodb-05:27017 req:1087 | db_api_production.getMore | SUCCEEDED | 1.181s
[61] pry(main)> c_fast.bills.excludes(_id: BSON::ObjectId('62753df4a54d7584e56ea829')).order(reference: :desc).limit(1000).pluck(:reference, :_id)
MONGODB | pro-app-mongodb-05:27017 req:1091 conn:1:1 | db_api_production.find | STARTED | {"find"=>"bills", "filter"=>{"deleted_at"=>nil, "customer_id"=>BSON::ObjectId('571636f44a506256d6000003'), "_id"=>{"$ne"=>BSON::ObjectId('62753df4a54d7584e56ea829')}}, "limit"=>1000, "sort"=>{"reference"=>-1}, "projection"=>{"reference"=>1, "_id"=>1...
MONGODB | pro-app-mongodb-05:27017 req:1091 | db_api_production.find | SUCCEEDED | 0.004s
MONGODB | pro-app-mongodb-05:27017 req:1092 conn:1:1 | db_api_production.getMore | STARTED | {"getMore"=>#<BSON::Int64:0x0000558bcd89c4d0 @value=166614148534>, "collection"=>"bills", "$db"=>"db_api_production", "$clusterTime"=>{"clusterTime"=>#<BSON::Timestamp:0x0000558bcd88eab0 @seconds=1652511516, @increment=1>, "signature"=>{"hash"=><...
MONGODB | pro-app-mongodb-05:27017 req:1092 | db_api_production.getMore | SUCCEEDED | 0.013s
The slow customer is taking 10 seconds and the fast one is taking 0.004s in the same query. and the slow customer has less than 600 documents and the fast client more than 35000. it has no sense for me.
We did on the bills collection a Reindex, we take the query over all customers and it seems too work at the beginnign but in thre second query it went slow again but the same customers are always slow than the fastest one
[1] pry(main)> Customer.all.collect do |c|
[1] pry(main)* starting = Process.clock_gettime(Process::CLOCK_MONOTONIC)
[1] pry(main)* c.bills.excludes(_id: BSON::ObjectId('62753df4a54d7584e56ea829')).order(reference: :desc).limit(1000).pluck(:reference_string, :id);nil
[1] pry(main)* ending = Process.clock_gettime(Process::CLOCK_MONOTONIC)
[1] pry(main)* [c.acronym, ending - starting]
[1] pry(main)* end
I cannot apply explain on pluck query. I reviewd the index and it worked correctly placed in the collection but doing explain it is slow on the same query
MONGODB | pro-app-mongodb-05:27017 req:1440 | dbapiproduction.explain | SUCCEEDED | 10.841s MONGODB | pro-app-mongodb-05:27017 req:2005 | dbapiproduction.explain | SUCCEEDED | 0.006s
obviously time, but also docsExamined
the query is the same, changing obyously de ids:
[23] pry(main)> h_slow["queryPlanner"]["parsedQuery"]
=> {"$and"=>
[{"customer_id"=>{"$eq"=>BSON::ObjectId('60c76b9e21225c002044f6c5')}},
{"deleted_at"=>{"$eq"=>nil}},
{"$nor"=>[{"_id"=>{"$eq"=>BSON::ObjectId('62753df4a54d7584e56ea829')}}]}]}
[24] pry(main)> h_fast["queryPlanner"]["parsedQuery"]
=> {"$and"=>
[{"customer_id"=>{"$eq"=>BSON::ObjectId('571636f44a506256d6000003')}},
{"deleted_at"=>{"$eq"=>nil}},
{"$nor"=>[{"_id"=>{"$eq"=>BSON::ObjectId('62753df4a54d7584e56ea829')}}]}]}
"inputStage": {
"advanced": 1000,
"direction": "backward",
"dupsDropped": 0,
"dupsTested": 0,
"executionTimeMillisEstimate": 0,
"indexBounds": {
"reference": [
"[MaxKey, MinKey]"
]
},
"indexName": "reference_1",
"indexVersion": 2,
"invalidates": 0,
"isEOF": 0,
"isMultiKey": false,
"isPartial": false,
"isSparse": false,
"isUnique": false,
"keyPattern": {
"reference": 1
},
"keysExamined": 1000,
"multiKeyPaths": {
"reference": []
},
"nReturned": 1000,
"needTime": 0,
"needYield": 0,
"restoreState": 10,
"saveState": 10,
"seeks": 1,
"seenInvalidated": 0,
"stage": "IXSCAN",
"works": 1000
},
"invalidates": 0,
"isEOF": 0,
"nReturned": 1000,
"needTime": 0,
"needYield": 0,
"restoreState": 10,
"saveState": 10,
"stage": "FETCH",
"works": 1000
},
"invalidates": 0,
"isEOF": 1,
"limitAmount": 1000,
"nReturned": 1000,
"needTime": 0,
"needYield": 0,
"restoreState": 10,
"saveState": 10,
"stage": "LIMIT",
"works": 1001
},
"executionSuccess": true,
"executionTimeMillis": 7,
"nReturned": 1000,
"totalDocsExamined": 1000,
"totalKeysExamined": 1000
}
"inputStage": {
"advanced": 604411,
"direction": "backward",
"dupsDropped": 0,
"dupsTested": 0,
"executionTimeMillisEstimate": 320,
"indexBounds": {
"reference": [
"[MaxKey, MinKey]"
]
},
"indexName": "reference_1",
"indexVersion": 2,
"invalidates": 0,
"isEOF": 1,
"isMultiKey": false,
"isPartial": false,
"isSparse": false,
"isUnique": false,
"keyPattern": {
"reference": 1
},
"keysExamined": 604411,
"multiKeyPaths": {
"reference": []
},
"nReturned": 604411,
"needTime": 0,
"needYield": 0,
"restoreState": 6138,
"saveState": 6138,
"seeks": 1,
"seenInvalidated": 0,
"stage": "IXSCAN",
"works": 604412
},
"invalidates": 0,
"isEOF": 1,
"nReturned": 523,
"needTime": 603888,
"needYield": 0,
"restoreState": 6138,
"saveState": 6138,
"stage": "FETCH",
"works": 604412
},
"invalidates": 0,
"isEOF": 1,
"limitAmount": 1000,
"nReturned": 523,
"needTime": 603888,
"needYield": 0,
"restoreState": 6138,
"saveState": 6138,
"stage": "LIMIT",
"works": 604412
},
"executionSuccess": true,
"executionTimeMillis": 9472,
"nReturned": 523,
"totalDocsExamined": 604411,
"totalKeysExamined": 604411
}
Why happen this differences, and what I can do to correct this collection
Sources
This article follows the attribution requirements of Stack Overflow and is licensed under CC BY-SA 3.0.
Source: Stack Overflow
| Solution | Source |
|---|