Why is MongoDB logging so many of my queries

Question

I have a NodeJS MongoDB that works just fine, only problem I notice is that mongo is logging so much of my queries. I tried different indexing strategies but it stays the same way. The communication between mongo and node is done by mongoose.

Query case 1:

Sun May 11 01:15:26.076 [conn5] query api.items query: { $query: { gameid: 209670, appid: 102 }, orderby: { price: -1 } } ntoreturn:0 ntoskip:0 nscanned:29 scanAndOrder:1 keyUpdates:0 numYields: 1 locks(micros) r:382458 nreturned:29 reslen:22686 240ms
Sun May 11 01:24:44.950 [conn5] query api.items query: { $query: { gameid: 248820, appid: 102 }, orderby: { price: -1 } } ntoreturn:0 ntoskip:0 nscanned:20 scanAndOrder:1 keyUpdates:0 locks(micros) r:78688 nreturned:20 reslen:16281 110ms

Items collection:

var itemSchema = new Schema({
    appid    : {type: Number, required: true},
    gameid   : {type: Number, required: true},
    name     : {type: String, required: true},
    hash     : {type: String, index: true},
    price    : Number,
    date     : Date
});

itemSchema.set('versionKey', false);
itemSchema.index({ appid: 1, gameid: 1 });
itemSchema.index({ gameid: 1 });

I have a set of around the 20.000 items, for all of them the appid is 102 and there are 800 gameid's. All of them have an unique ObjectId.

RockMongo tells me the following indexes are available:

When I do an explain on the query:

Response from server:
{
   "cursor": "BtreeCursor appid_1_gameid_1",
   "isMultiKey": false,
   "n": NumberInt(20),
   "nscannedObjects": NumberInt(20),
   "nscanned": NumberInt(20),
   "nscannedObjectsAllPlans": NumberInt(60),
   "nscannedAllPlans": NumberInt(60),
   "scanAndOrder": true,
   "indexOnly": false,
   "nYields": NumberInt(0),
   "nChunkSkips": NumberInt(0),
   "millis": NumberInt(25),
   "indexBounds": {
     "appid": [
       [
         102,
         102
      ] 
    ],
     "gameid": [
       [
         248820,
         248820 
      ] 
    ] 
  },
   "allPlans": [
     {
       "cursor": "BtreeCursor appid_1_gameid_1",
       "n": NumberInt(20),
       "nscannedObjects": NumberInt(20),
       "nscanned": NumberInt(20),
       "indexBounds": {
         "appid": [
           [
             102,
             102
          ] 
        ],
         "gameid": [
           [
             248820,
             248820 
          ] 
        ] 
      } 
    },
     {
       "cursor": "BtreeCursor gameid_1",
       "n": NumberInt(20),
       "nscannedObjects": NumberInt(20),
       "nscanned": NumberInt(20),
       "indexBounds": {
         "gameid": [
           [
             248820,
             248820 
          ] 
        ] 
      } 
    },
     {
       "cursor": "BasicCursor",
       "n": NumberInt(0),
       "nscannedObjects": NumberInt(20),
       "nscanned": NumberInt(20),
       "indexBounds": [

      ] 
    } 
  ],
   "oldPlan": {
     "cursor": "BtreeCursor appid_1_gameid_1",
     "indexBounds": {
       "appid": [
         [
           102,
           102
        ] 
      ],
       "gameid": [
         [
           248820,
           248820 
        ] 
      ] 
    } 
  },
   "server": ---
}

Answer 1

MongoDB logs slow queries that are longer than 100ms (profile level 1, default slowms). You can change the threshold by using profile command.

By looking at your explain command I think that the performance of your server is the problem. Your explain command finished in 25ms so it could only be a temporary thing caused by high load on the server. Check your MMS stats.

Few suggestions regarding your indexes. You should consider creating an compound index from gameid and price columns because the MongoDB will return an error if the sort function consumes more than 32MB. If all documents in the collection have the same appId then you can remove the index from that field because it's not being used effectively.