title: mongodb poor query performance and profiler estimates very high
body: <p>My mongodb database is roughly 50Gi in size. There are approximately 45K collections ranging wildly in size. the largest has on the order of &lt; 1Million documents. </p>
  
  <p>I'm running mongodb version 3.6.8 in AWS on r5.xlarge (32Gi memory, 4 vCPU) with a 500Gi gp2 SSD disk mounted as a persistent volume. It is <em>not</em> sharded, but replicated with 1 Primary and 2 Secondary nodes.</p>
  
  <p>Much of the time the queries perform reasonably well. However, every so often queries (inserts, updates, fetches--it doesn't seem to matter) take a "very long time" to complete. I am trying to figure out what is causing this.</p>
  
  <p>I enabled profiling for queries that take longer than 10 seconds.</p>
  
  <p>Here is a case in point that boggles the mind. It is an update on a collection with 5 documents where the qualification is on the _id property. It takes 20 seconds to run. The profiler shows:</p>
  
  <pre><code>{
      "op" : "update",
      "ns" : "bar.PumpStatus__PumpEventDrivenAppNS",
      "command" : {
          "q" : {
              "_id" : ObjectId("5e43f4b9aae591154193999a")
          },
          "u" : {
              "$inc" : {
                  "foo_version" : 1
              },
              "$set" : {
                  "PumpId" : "Pump1",
                  "Temp" : NumberLong(197),
                  "RPMS" : NumberLong(3885),
                  "Time" : ISODate("2020-03-04T20:39:11.065Z"),
                  "foo_modifiedAt" : ISODate("2020-03-04T20:39:11.946Z"),
                  "foo_modifiedBy" : "439b96af-558e-4372-a7b9-d245f48d3d3d"
              }
          },
          "multi" : true,
          "upsert" : false
      },
      "keysExamined" : 1,
      "docsExamined" : 1,
      "nMatched" : 1,
      "nModified" : 1,
      "writeConflicts" : 1,
      "numYield" : 1,
      "locks" : {
          "Global" : {
              "acquireCount" : {
                  "r" : NumberLong(3),
                  "w" : NumberLong(3)
              }
          },
          "Database" : {
              "acquireCount" : {
                  "w" : NumberLong(3)
              }
          },
          "Collection" : {
              "acquireCount" : {
                  "w" : NumberLong(2)
              }
          },
          "oplog" : {
              "acquireCount" : {
                  "w" : NumberLong(1)
              }
          }
      },
      "millis" : 20001,
      "planSummary" : "IDHACK",
      "execStats" : {
          "stage" : "UPDATE",
          "nReturned" : 0,
          "executionTimeMillisEstimate" : 20008,
          "works" : 3,
          "advanced" : 0,
          "needTime" : 1,
          "needYield" : 1,
          "saveState" : 1,
          "restoreState" : 1,
          "isEOF" : 1,
          "invalidates" : 0,
          "nMatched" : 1,
          "nWouldModify" : 1,
          "nInvalidateSkips" : 0,
          "wouldInsert" : false,
          "fastmodinsert" : false,
          "inputStage" : {
              "stage" : "IDHACK",
              "nReturned" : 1,
              "executionTimeMillisEstimate" : 18351,
              "works" : 1,
              "advanced" : 1,
              "needTime" : 0,
              "needYield" : 0,
              "saveState" : 3,
              "restoreState" : 2,
              "isEOF" : 1,
              "invalidates" : 0,
              "keysExamined" : 1,
              "docsExamined" : 1
          }
      },
      "ts" : ISODate("2020-03-04T20:39:31.948Z"),
      "client" : "10.10.158.164",
      "appName" : "io.myorg.mongodb",
      "allUsers" : [
          {
              "user" : "foo",
              "db" : "bar"
          }
      ],
      "user" : "foo@bar"
  }
  </code></pre>
  
  <p>mongodb <em>estimates</em> that using IDHACK to find the document will require 18.351 seconds and that the overall execution will take 20.008 seconds. Lo and behold the execution time clocked in at 20.001. </p>
  
  <p>I find these numbers difficult to believe. can they be trusted? and if so, what could possibly be happening to cause such a slow execution time? </p>
  
  <p>the collection is very small, there is no reported lock wait, if i run the equivalent find by hand, it returns instantly. as near as I can tell the CloudWatch metrics for the volume do not indicate very slow read or write operations. latencies are low and IOPS nowhere near the limit.</p>
  
  <p>areas that i know can be improved:</p>
  
  <ul>
  <li>enable <code>directoryForIndexes</code> to split collections and indexes across 2 volumes</li>
  <li>use <code>XFS</code> on the volume</li>
  <li>ensure huge pages are disabled (i think they are)</li>
  </ul>
  
  <p>I'm skeptical that any of the above will relieve the pain. i suspect that i am doing something (else) basic completely wrong. </p>
  
  <p>any thoughts on what might be happening here?</p>