← back to the blog


Measuring mongoDB query performance

Posted on May 30th, 2018 in Document Stores by Moditha Hewasinghage

MongoDB has become one of the most popular NoSQL data stores now. It is widely used in both commercial and non-commercial environments. The main reason behind the broad adaptation of MongoDB is its flexibility and the inherent JSON (BSON) data format which is a familiar data format for the web developers. The schema-less concept in MongoDB enables the end users to get their application and prototypes up and running worrying less about the data storage compared to traditional RDBMS (Relational Database Management Systems), where much more emphasis and attention is given to the initial data design of the system.

There are no specific rules for data design for MongoDB, but rather guidelines to design the data according to the possible queries that could be executed. Nevertheless, this inherent flexibility of MongoDB could create drawbacks in the long run such as expensive queries due to the bad design, especially for ad-hoc queries.

  1. Using explain()
  2. Logging the database

 The explain() function of MongoDB describes the execution plan for the queries. A query can have multiple execution plans, and MongoDB query planner executes all the possible plans in parallel (unlike in most RDBMS where the query planner calculates and decides the best plan according to a cost function). Whatever the plan that wins, is executed to give the results to the user and also the query plan is cached to be used for similar queries in the future. But, this does not cache the query results in other words if the same query is executed once again it will only use the cached plan, but not the previous results.

  •  IDHACK retrieving by document id
  • COLLSCAN for a collection scan
  • IXSCAN for scanning index keys
  • FETCH for retrieving documents
  • SHARD_MERGE for merging results from shards
  • SHARDING_FILTER for filtering out orphan documents from shards

 

Explain() has three levels of details

  • Query planner mode(default) : Shows the plan selected by the query planner
  • executionStats: Shows the query planner details and the execution details of the winning plan    
  • allPlansExecution: In addition to the execution stats for the winning plan this also includes the execution details of the rejected plans as well.

 

In the following example. There are two indexes available on the first_name field, and the query planner uses the simple index instead of the compound index (this is in the rejected plan).  If there are no usable indexes available, MongoDB will resort to scanning all the documents. The following stages and access methods are available for the query planner results.

 

  • IDHACK retrieving by document id
  • COLLSCAN for a collection scan
  • IXSCAN for scanning index keys
  • FETCH for retrieving documents
  • SHARD_MERGE for merging results from shards
  • SHARDING_FILTER for filtering out orphan documents from shards

 

 

There are many parameters used by the query planner in deciding the winning plan such the number of documents examined and the time  taken. If any of the plans already exceeds one of those parameters compared to the other plans, the execution is halted.

{
  "queryPlanner": {
    "plannerVersion": 1,
    "namespace": "M201.people",
    "indexFilterSet": false,
    "parsedQuery": {
      "first_name": {
        "$eq": "Christopher"
      }
    },
    "winningPlan": {
      "stage": "FETCH",
      "inputStage": {
        "stage": "IXSCAN",
        "keyPattern": {
          "first_name": 1
        },
        "indexName": "f3",
        "isMultiKey": false,
        "multiKeyPaths": {
          "first_name": [
           
          ]
        },
        "isUnique": false,
        "isSparse": false,
        "isPartial": false,
        "indexVersion": 2,
        "direction": "forward",
        "indexBounds": {
          "first_name": [
            "[\"Christopher\", \"Christopher\"]"
          ]
        }
      }
    },
    "rejectedPlans": [
      {
        "stage": "FETCH",
        "inputStage": {
          "stage": "IXSCAN",
          "keyPattern": {
            "first_name": 1,
            "last_name": 1
          },
          "indexName": "f1",
          "isMultiKey": false,
          "multiKeyPaths": {
            "first_name": [
             
            ],
            "last_name": [
             
            ]
          },
          "isUnique": false,
          "isSparse": false,
          "isPartial": false,
          "indexVersion": 2,
          "direction": "forward",
          "indexBounds": {
            "first_name": [
              "[\"Christopher\", \"Christopher\"]"
            ],
            "last_name": [
              "[MinKey, MaxKey]"
            ]
          }
        }
      }
    ]
  },
  "executionStats": {
    "executionSuccess": true,
    "nReturned": 690,
    "executionTimeMillis": 1,
    "totalKeysExamined": 690,
    "totalDocsExamined": 690,
    "executionStages": {
      "stage": "FETCH",
      "nReturned": 690,
      "executionTimeMillisEstimate": 0,
      "works": 691,
      "advanced": 690,
      "needTime": 0,
      "needYield": 0,
      "saveState": 6,
      "restoreState": 6,
      "isEOF": 1,
      "invalidates": 0,
      "docsExamined": 690,
      "alreadyHasObj": 0,
      "inputStage": {
        "stage": "IXSCAN",
        "nReturned": 690,
        "executionTimeMillisEstimate": 0,
        "works": 691,
        "advanced": 690,
        "needTime": 0,
        "needYield": 0,
        "saveState": 6,
        "restoreState": 6,
        "isEOF": 1,
        "invalidates": 0,
        "keyPattern": {
          "first_name": 1
        },
        "indexName": "f3",
        "isMultiKey": false,
        "multiKeyPaths": {
          "first_name": [
           
          ]
        },
        "isUnique": false,
        "isSparse": false,
        "isPartial": false,
        "indexVersion": 2,
        "direction": "forward",
        "indexBounds": {
          "first_name": [
            "[\"Christopher\", \"Christopher\"]"
          ]
        },
        "keysExamined": 690,
        "seeks": 1,
        "dupsTested": 0,
        "dupsDropped": 0,
        "seenInvalidated": 0
      }
    },
    "allPlansExecution": [
      {
        "nReturned": 101,
        "executionTimeMillisEstimate": 0,
        "totalKeysExamined": 101,
        "totalDocsExamined": 101,
        "executionStages": {
          "stage": "FETCH",
          "nReturned": 101,
          "executionTimeMillisEstimate": 0,
          "works": 101,
          "advanced": 101,
          "needTime": 0,
          "needYield": 0,
          "saveState": 1,
          "restoreState": 1,
          "isEOF": 0,
          "invalidates": 0,
          "docsExamined": 101,
          "alreadyHasObj": 0,
          "inputStage": {
            "stage": "IXSCAN",
            "nReturned": 101,
            "executionTimeMillisEstimate": 0,
            "works": 101,
            "advanced": 101,
            "needTime": 0,
            "needYield": 0,
            "saveState": 1,
            "restoreState": 1,
            "isEOF": 0,
            "invalidates": 0,
            "keyPattern": {
              "first_name": 1,
              "last_name": 1
            },
            "indexName": "f1",
            "isMultiKey": false,
            "multiKeyPaths": {
              "first_name": [
               
              ],
              "last_name": [
               
              ]
            },
            "isUnique": false,
            "isSparse": false,
            "isPartial": false,
            "indexVersion": 2,
            "direction": "forward",
            "indexBounds": {
              "first_name": [
                "[\"Christopher\", \"Christopher\"]"
              ],
              "last_name": [
                "[MinKey, MaxKey]"
              ]
            },
            "keysExamined": 101,
            "seeks": 1,
            "dupsTested": 0,
            "dupsDropped": 0,
            "seenInvalidated": 0
          }
        }
      },
      {
        "nReturned": 101,
        "executionTimeMillisEstimate": 0,
        "totalKeysExamined": 101,
        "totalDocsExamined": 101,
        "executionStages": {
          "stage": "FETCH",
          "nReturned": 101,
          "executionTimeMillisEstimate": 0,
          "works": 101,
          "advanced": 101,
          "needTime": 0,
          "needYield": 0,
          "saveState": 1,
          "restoreState": 1,
          "isEOF": 0,
          "invalidates": 0,
          "docsExamined": 101,
          "alreadyHasObj": 0,
          "inputStage": {
            "stage": "IXSCAN",
            "nReturned": 101,
            "executionTimeMillisEstimate": 0,
            "works": 101,
            "advanced": 101,
            "needTime": 0,
            "needYield": 0,
            "saveState": 1,
            "restoreState": 1,
            "isEOF": 0,
            "invalidates": 0,
            "keyPattern": {
              "first_name": 1
            },
            "indexName": "f3",
            "isMultiKey": false,
            "multiKeyPaths": {
              "first_name": [
               
              ]
            },
            "isUnique": false,
            "isSparse": false,
            "isPartial": false,
            "indexVersion": 2,
            "direction": "forward",
            "indexBounds": {
              "first_name": [
                "[\"Christopher\", \"Christopher\"]"
              ]
            },
            "keysExamined": 101,
            "seeks": 1,
            "dupsTested": 0,
            "dupsDropped": 0,
            "seenInvalidated": 0
          }
        }
      }
    ]
  },
  "serverInfo": {
    "host": "DESKTOP-4QFP4NN",
    "port": 27017,
    "version": "3.6.4",
    "gitVersion": "d0181a711f7e7f39e60b5aeb1dc7097bf6ae5856"
  },
  "ok": 1
}

 

 

The database profiler in MongoDB is turned off my default. This collects detailed information about the commands executed against a MongoDB instance. This not only includes the CRUD operations but also the administration and configuration information. The collected information is stored in system.profile collection.

There are 3 levels of profiling available for the profiler.

  • 0: Does not collect any data
  • 1: Collects data for operations that takes longer than a pre-defined threshold
  • 2: Collects data for all the operations

To enable profiling

db.setProfilingLevel(2) 

To explore the profiler results one can use the following command.

db.system.profile.find().limit(10)

The result of a profile command looks as follows.

 

{
  "op": "command",
  "ns": "M201.people",
  "command": {
    "explain": {
      "find": "people",
      "filter": {
        "first_name": "Christopher"
      }
    },
    "verbosity": "allPlansExecution",
    "$db": "M201"
  },
  "numYield": 19,
  "locks": {
    "Global": {
      "acquireCount": {
        "r": NumberLong(40)
      }
    },
    "Database": {
      "acquireCount": {
        "r": NumberLong(20)
      }
    },
    "Collection": {
      "acquireCount": {
        "r": NumberLong(20)
      }
    }
  },
  "responseLength": 3741,
  "protocol": "op_msg",
  "millis": 265,
  "ts": ISODate("2018-05-28T11:32:09.243Z"),
  "client": "127.0.0.1",
  "appName": "MongoDB Shell",
  "allUsers": [
   
  ],
  "user": ""
}

The information avalilable from the logger is similar to the information provided by the query planner. But, limited to the actual query execution details. This is useful to identify the bottlenecks of a running instance of MongoDB.

MongoDB manual