Poor perfomance in mongoid rails queries depending on index

Working with Data
, , ,
1

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

2

It’s hard to tell what’s going on but it may be easier if you can access the mongod log file and include the log lines generated when the slow query runs - it will show exactly what’s happening during the query which is different than when you run explain.

Is it possible for you to access the mongod logs? Also MongoDB 3.6 is really old - are you able to upgrade to a more recent version?

Asya