Slow queries on MongoDB

During a typical revision of mongod’s logs, we could find slow queries, by default, those queries that take more >100ms. You can change this time with –slowms <integer> parameter when you launch a mongod process or using a configuration file.

This is an expample of log message:

2018-07-02T12:26:24.580-0500 I COMMAND [conn11186210] command test.CARcommand: getMore { getMore: 164459457945, collection: “CAR” } planSummary: IXSCAN { _id: 1 } cursorid:164459457945 keysExamined:6488 docsExamined:6488 keyUpdates:0 writeConflicts:0 numYields:50 nreturned:6488 reslen:4194880 locks:{ Global: { acquireCount: { r: 102 } }, MMAPV1Journal: { acquireCount: { r: 102 } }, Database: { acquireCount: { r: 51 } }, Collection: { acquireCount: { R: 51 }, acquireWaitCount: { R: 51 }, timeAcquiringMicros: { R: 140362206 } } } protocol:op_query 140378ms

Components associated:

• Timestamp: 2018-07-02T12:26:24.580-0500
• Severity Levels: I (Informational)
• Component: COMMAND (Message related to Database commands)
• Context: conn11186210 (connections)
• Message:
  • Namespace: test.car (Is formed by databasename dot collection)
  • Command: getMore (Returns batches of documents currently pointed to by the cursor)
    • getMore { getMore: 164459457945, collection: “CAR” }
  • planSummary: IXSCAN { _id: 1 } (scanning index keys by default _id:1)
  • cursorid:164459457945 (The ID of the cursor accessed by a query and getmore operations)
  • keysExamined:6488 (The number of index keys that MongoDB scanned in order to carry out the operation)
  • docsExamined:6488 (The number of documents in the collection that MongoDB scanned in order to carry out the operation)
  • keyUpdates:0 (The number of index keys upodated for a given write operation)
  • writeConflicts:0 (The number of conflicts encountered during the write operation)
  • numYields:50 (The number of times the operation yielded to allow other operations to complete)
  • nreturned:6488 (The number of documents returned by the operation)
  • reslen:4194880 (responseLength, the length in bytes of the operation’s result document)
  • locks (provides information for various lock types and lock modes )
    • Global: { acquireCount: { r: 102 } } (Number of times the operation acquired the lock in the specified mode)
    • MMAPV1Journal: { acquireCount: { r: 102 } }  (Number of times the operation acquired the lock in the specified mode)
    • Database: { acquireCount: { r: 51 } } (Number of times the operation acquired the lock in the specified mode)
    • Collection: { acquireCount: { R: 51 }, acquireWaitCount: { R: 51 }, timeAcquiringMicros: { R: 140362206 } }
      • acquireCount: { R: 51 }  (Number of times the operation acquired the lock in the specified mode)
      • acquireWaitCount: { R: 51 }  (Number of times the operation had to wait for the acquireCount lock acquisitions because the locks were held in a conflicting mode)
      • timeAcquiringMicros: { R: 140362206 } (Cumulative time in microseconds that the operation had to wait to acquire the locks)
    • You can find the description of every part here
  • protocol:op_query 140378ms (Total time of this transaction)

Conclusion

In this expample the getmore command takes 140.378 seconds to resolve, the root cause are locks.

If keysExamined is much higher than nreturned, the database is scanning many index keys to find the result documents. Consider creating or adjusting indexes to improve query performance. In this example isn’t the case.

As you can see, this MongoDB installation is using MMAPv1 storage engine, I recommend using WiredTiger Storage Engine in case of multiple clients want to modify different documents of a collection at the same time.