title: Slow mongodb query with low number of documents scanned
body: <p>I have a replica set of 3 MongoDB instances. The instances have 8GB of RAM and Dual Core 2.27 GHz CPUs. All instances are running version 2.2.2 (I saw the same behavior from 2.0.1).</p>
  
  <p>Here's my issue: Our primary instance (master of the replica set) recently acquired the habit of crawling to 100% CPU every 2 days. Tracking down the cause, I decided to run the MongoDB profiler. I found hundreds of extremely slow queries. Here is an example:</p>
  
  <pre><code>&gt; db.system.profile.find()
  { 
      "ts" : ISODate("2012-12-16T20:31:39.078Z"), 
      "op" : "command", 
      "ns" : "stylesaint.$cmd", 
      "command" : { 
          "count" : "tears", 
          "query" : { 
              "_id" : { "$gt" : ObjectId("50cdeadeaf58d3de96000294") }, 
              "active" : true, 
              "is_image_processed" : true, 
              "hidden_from_feed" : false, 
              "hidden_from_public_feeds" : false
          }, 
          "fields" : null 
      }, 
      "ntoreturn" : 1, 
      "responseLength" : 48, 
      "millis" : 13930, 
      "client" : "#########"
  }
  </code></pre>
  
  <p>From what I've read about mongodb, the natural next step in these situations is to try explain()ing those queries. However, explain() does not explain the slowness of the query:</p>
  
  <pre><code>&gt; db.tears.find({ "_id" : { "$gt" : ObjectId("50cdeadeaf58d3de96000294") }, "active" : true, "is_image_processed" : true, "hidden_from_feed" : false, "hidden_from_public_feeds" : false }).explain()
  {
      "cursor" : "BtreeCursor id",
      "isMultiKey" : false,
      "n" : 4,
      "nscannedObjects" : 5,
      "nscanned" : 5,
      "nscannedObjectsAllPlans" : 23,
      "nscannedAllPlans" : 25,
      "scanAndOrder" : false,
      "indexOnly" : false,
      "nYields" : 0,
      "nChunkSkips" : 0,
      "millis" : 0,
      "indexBounds" : { 
          "_id" : [ 
              [ 
                  ObjectId("50cdeadeaf58d3de96000294"), 
                  ObjectId("ffffffffffffffffffffffff")
              ]
          ]
      },
      "server" : "#########"
  }
  </code></pre>
  
  <p>Scanning 5 documents should not take 13 seconds. Something else is going on that is slowing down the query. Maybe some other query is starving the server's resources? However, I don't know where to look. Any advice you can offer is appreciated.</p>
  
  <p><strong>MongoDB Logs</strong></p>
  
  <p>I couldn't find any warnings in the startup process:</p>
  
  <pre><code>***** SERVER RESTARTED *****
  
  
  Sun Dec 16 21:02:56 [initandlisten] MongoDB starting : pid=...
  Sun Dec 16 21:02:56 [initandlisten] db version v2.2.2, pdfile version 4.5
  Sun Dec 16 21:02:56 [initandlisten] git version: ...   
  Sun Dec 16 21:02:56 [initandlisten] build info: Linux 2.6.21.7-2 ...
  Sun Dec 16 21:02:56 [initandlisten] options: { config: "/etc/mongodb.conf", dbpath: "/data/mongodb", logappend: "true", logpath: "/var/log/mongodb/mongodb.log", replSet: "...", rest: "true" }
  Sun Dec 16 21:02:56 [initandlisten] journal dir=/data/mongodb/journal
  Sun Dec 16 21:02:56 [initandlisten] recover : no journal files present, no recovery needed
  Sun Dec 16 21:02:56 [initandlisten] waiting for connections on port ...
  Sun Dec 16 21:02:56 [websvr] admin web console waiting for connections on port ...
  Sun Dec 16 21:02:56 [initandlisten] connection accepted from ...
  Sun Dec 16 21:02:56 [conn1] end connection ... (0 connections now open)
  Sun Dec 16 21:02:56 [initandlisten] connection accepted from ... #2 (1 connection now open)
  Sun Dec 16 21:02:56 [rsStart] replSet I am ...
  Sun Dec 16 21:02:56 [rsStart] replSet STARTUP2
  Sun Dec 16 21:02:56 [rsHealthPoll] replSet member ... is up
  Sun Dec 16 21:02:56 [rsHealthPoll] replSet member ... is now in state SECONDARY
  Sun Dec 16 21:02:57 [initandlisten] connection accepted from ... #3 (2 connections now open)
  Sun Dec 16 21:02:57 [rsSync] replSet SECONDARY
  Sun Dec 16 21:02:58 [initandlisten] connection accepted from ... #4 (3 connections now open)
  Sun Dec 16 21:02:58 [initandlisten] connection accepted from ... #5 (4 connections now open)
  Sun Dec 16 21:02:58 [conn5] end connection ... (3 connections now open)
  Sun Dec 16 21:02:58 [rsHealthPoll] replSet member ... is up
  Sun Dec 16 21:02:58 [rsHealthPoll] replSet member ... is now in state PRIMARY
  Sun Dec 16 21:02:59 [initandlisten] connection accepted from ... #6 (4 connections now open)
  Sun Dec 16 21:03:00 [initandlisten] connection accepted from ... #7 (5 connections now open)
  Sun Dec 16 21:03:02 [conn7] end connection ... (4 connections now open)
  Sun Dec 16 21:03:03 [rsBackgroundSync] replSet syncing to: ...
  Sun Dec 16 21:03:04 [rsSyncNotifier] replset setting oplog notifier to ...
  Sun Dec 16 21:03:06 [conn2] end connection ... (3 connections now open)
  Sun Dec 16 21:03:06 [initandlisten] connection accepted from ... #8 (4 connections now open)
  Sun Dec 16 21:03:08 [initandlisten] connection accepted from ... #9 (5 connections now open)
  Sun Dec 16 21:03:13 [initandlisten] connection accepted from ... #10 (6 connections now open)
  Sun Dec 16 21:03:13 [conn10] end connection ... (5 connections now open)
  Sun Dec 16 21:03:13 [initandlisten] connection accepted from ... #11 (6 connections now open)
  Sun Dec 16 21:03:15 [conn3] end connection ... (5 connections now open)
  Sun Dec 16 21:03:16 [rsHealthPoll] replSet member .... is now in state SECONDARY
  Sun Dec 16 21:03:16 [rsMgr] replSet info electSelf 1
  Sun Dec 16 21:03:16 [rsMgr] replSet PRIMARY
  </code></pre>
  
  <p><strong>Re: Request for more info</strong></p>
  
  <p>At the moment, MongoDB is functioning normally; there are no queries above 100ms. As soon as 100% CPU happens again, I'll post more info about system resources.</p>