MongoDB Performance — Explain

When it comes to database design or analytic, query performance optimistic is always a hot topic. MongoDB provides a really great feather, which is “explain”, on helping DBAs to understand what’s going on inside the query command execution. After evaluating the explain, I have to say it is a really helpful and well-designed feather in terms of performance. In this article, I’d like discussing more in detailed about explain. It will help beginners on using it.

Explain in Details

From MongoDB official document, we know that explain supports three verbosity types, queryPlanner, executionStats and allPlansExecution. Let me explain each of them in details.

[Notes]: In this article, I am going to use below template collection to illustrate the output of explain query. It is defined in a collection users under database template. The total number of document is this collection is 1000000.

{
"_id" : ObjectId("5950cb3f90366d2e22735c26"),
"user" : {
"name" : {
"last" : "Brown",
"first" : "Jackson"
},
"gender" : "female",
"created_at" : "2014-01-03T06:51:48",
"is_active" : false,
"phone_no" : NumberLong("6371567040"),
"address" : {
"city" : "Bronx",
"house_no" : 64,
"street" : "fq6s5rGl6F",
"zip_code" : 97104
},
"age" : 77
},
"tags" : [ ]
}

If you want to create a collection of above template in your MongoDB instance, you can follow the example from https://github.com/rueckstiess/mtools/wiki/mgenerate. MTools is a greate tool to help to create/generate all types of mongod instances.

queryPlanner

This is the default explain verbosity parameter that runs the query optimizer to choose the “winning plan” for the query under evaluation. Consider below simple query command:

>  db.users.find()
{ "_id" : ObjectId("595070188f7898cf41ba64f0"), "user" : { "name" : { "last" : "Brown", "first" : "Jackson" }, "gender" : "female", "created_at" : "2014-01-03T06:51:48", "is_active" : false, "phone_no" : NumberLong("6371567040"), "address" : { "city" : "Bronx", "house_no" : 64, "street" : "fq6s5rGl6F", "zip_code" : 97104 }, "age" : 77 }, "tags" : [ ] }

It is nothing special but do you really know what going on underneath. Let see what explain gives us in this query command:

> db.users.explain().find()
{
"queryPlanner" : {
"plannerVersion" : 1,
"namespace" : "template.users",
"indexFilterSet" : false,
"parsedQuery" : {
},
"winningPlan" : {
"stage" : "COLLSCAN",
"direction" : "forward"
},
"rejectedPlans" : [ ]
},
"serverInfo" : {
"host" : "c880710e2e77",
"port" : 27017,
"version" : "3.4.4",
"gitVersion" : "888390515874a9debd1b6c5d36559ca86b44babd"
},
"ok" : 1
}

the above explain output gives you some explanations about the execution detailed analysis. The “serverInfo” and “ok” sections are quite straight forward, I don’t want to spend time on them. Let’s focus on “queryPlanner” second for now.

“winningPlan” is the most important second in this output. It gives you the plan selected by the query optimizer. A tree of stages is used to present a Mongo plain under “winningPlan”. In this case, there is only one stage which is “COLLSCAN”. In most cases, a stage can have an “inputStage”, or it may have “inputStages” if it includes more than one child stages.

Let’s observe a more complicated example as below:

> db.users.explain().find({"user.age": {$gt: 10}}).limit(10)
{
"queryPlanner" : {
"plannerVersion" : 1,
"namespace" : "template.users",
"indexFilterSet" : false,
"parsedQuery" : {
"user.age" : {
"$gt" : 10
}
},
"winningPlan" : {
"stage" : "LIMIT",
"limitAmount" : 10,
"inputStage" : {
"stage" : "COLLSCAN",
"filter" : {
"user.age" : {
"$gt" : 10
}
},
"direction" : "forward"
}
},
"rejectedPlans" : [ ]
},
"serverInfo" : {
"host" : "c880710e2e77",
"port" : 27017,
"version" : "3.4.4",
"gitVersion" : "888390515874a9debd1b6c5d36559ca86b44babd"
},
"ok" : 1
}

The “winningPlan” includes a LIMIT stage where a COLLSCAN stage inside it. We need to read the stage tree from leaf to the top. What is actually happening is that Mongo does a “COLLSCAN” query for finding the user who is older than 10 years followed by a “LIMIT” stage that limits the output to 10 documents.

executionStats

In addition to return the “winningPlan”, executionStats also gives details of each stage. Let check the same query on “executionStats”.

>  db.users.explain("executionStats").find({"user.age": {$gt: 10}})
{
"queryPlanner" : {
"plannerVersion" : 1,
"namespace" : "template.users",
"indexFilterSet" : false,
"parsedQuery" : {
"user.age" : {
"$gt" : 10
}
},
"winningPlan" : {
"stage" : "COLLSCAN",
"filter" : {
"user.age" : {
"$gt" : 10
}
},
"direction" : "forward"
},
"rejectedPlans" : [ ]
},
"executionStats" : {
"executionSuccess" : true,
"nReturned" : 891295,
"executionTimeMillis" : 344,
"totalKeysExamined" : 0,
"totalDocsExamined" : 1000000,
"executionStages" : {
"stage" : "COLLSCAN",
"filter" : {
"user.age" : {
"$gt" : 10
}
},
"nReturned" : 891295,
"executionTimeMillisEstimate" : 272,
"works" : 1000002,
"advanced" : 891295,
"needTime" : 108706,
"needYield" : 0,
"saveState" : 7813,
"restoreState" : 7813,
"isEOF" : 1,
"invalidates" : 0,
"direction" : "forward",
"docsExamined" : 1000000
}
},
"serverInfo" : {
"host" : "c880710e2e77",
"port" : 27017,
"version" : "3.4.4",
"gitVersion" : "888390515874a9debd1b6c5d36559ca86b44babd"
},
"ok" : 1
}

The output of explain is shown in json format including a lot information. Sometimes it is hard to read. Please look at below image for the output. One thing need to be noticed is that below graphic image is generated in different run of above command. So the milliseconds shown between above json and below image may be a little different. The number of documents related fields should have the same value. In below commands I will show both the json and graphic screenshot.

what you get in this time has one more section, “executionStats”. It contains statistics about each winning plan query execution. Let’s look at some of the statistics that may be interested you.

  1. nReturned
     it gives the number of the document returned in this query (which is how many users are older than 10). To approve that, simply type this command “db.users.find({“user.age”: {$gt: 10}}).count()” on your mongo, you can get the same result as 3534.
  2. executionTimeMillis
    the execution time of this query in millisecond. It is really an important factor for us to understand your query performance.
  3. filter
    this is just the condition part of your query command.
  4. docsExamined
    the number of document examined in order to find all matched data which is “user age greater than 10”.
  5. totalDocsExamined
    It is same as docsExamined but gives the total number of examined document from all stages.

allPlansExecution

similar with executionStats, allPlansExecution evaluates each plan performance and choose the best one as winning plan.

Use Explain to Improve Performance

When it comes to performance, we usually need to consider creating a few index. Let’s evaluate a query without indexes first:

> db.users.explain("executionStats").find({"user.age":{$lt:10}})
...
"executionStats" : {
"executionSuccess" : true,
"nReturned" : 98716,
"executionTimeMillis" : 341,
"totalKeysExamined" : 0,
"totalDocsExamined" : 1000000,
"executionStages" : {
"stage" : "COLLSCAN",
"filter" : {
"user.age" : {
"$lt" : 10
}
},
"nReturned" : 98716,
"executionTimeMillisEstimate" : 291,
"works" : 1000002,
"advanced" : 98716,
"needTime" : 901285,
"needYield" : 0,
"saveState" : 7812,
"restoreState" : 7812,
"isEOF" : 1,
"invalidates" : 0,
"direction" : "forward",
"docsExamined" : 1000000
}
},
...

It tells you that the number of returned document is 98716 but examined 1000000 document (which is the total number of our collection). In other words, in order to get 98716 document, it has to examine the whole collection. That’s a pretty bad performance since we unnecessarily examined 901284 documents. Therefore the total execution time is 292 milliseconds.

Let’s create two indexes on the collection we used before to see how they improve the performance.

> db.users.createIndex({"user.age":1})
> db.users.createIndex({"user.name.first":1})

after creating these indexes successfully, you can use below command to verify them:

> db.user.getIndexes()
[
{
"v" : 2,
"key" : {
"_id" : 1
},
"name" : "_id_",
"ns" : "users.user"
},
{
"v" : 2,
"key" : {
"user.age" : 1
},
"name" : "user.age_1",
"ns" : "users.user"
},
{
"v" : 2,
"key" : {
"user.name.first" : 1
},
"name" : "user.name.first_1",
"ns" : "users.user"
}
]

you can see from above output that two indexes have been created, “user.age” and “user.name.first”. Next, let’s evaluate the same query on this collection:

> db.users.explain("executionStats").find({"user.age":{$lt:10}})
...
"executionStats" : {
"executionSuccess" : true,
"nReturned" : 98716,
"executionTimeMillis" : 87,
"totalKeysExamined" : 98716,
"totalDocsExamined" : 98716,
"executionStages" : {
"stage" : "FETCH",
"nReturned" : 98716,
"executionTimeMillisEstimate" : 60,
"works" : 98717,
"advanced" : 98716,
"needTime" : 0,
"needYield" : 0,
"saveState" : 771,
"restoreState" : 771,
"isEOF" : 1,
"invalidates" : 0,
"docsExamined" : 98716,
"alreadyHasObj" : 0,
"inputStage" : {
"stage" : "IXSCAN",
"nReturned" : 98716,
"executionTimeMillisEstimate" : 20,
"works" : 98717,
"advanced" : 98716,
"needTime" : 0,
"needYield" : 0,
"saveState" : 771,
"restoreState" : 771,
"isEOF" : 1,
"invalidates" : 0,
"keyPattern" : {
"user.age" : 1
},
"indexName" : "user.age_1",
"isMultiKey" : false,
"multiKeyPaths" : {
"user.age" : [ ]
},
"isUnique" : false,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 2,
"direction" : "forward",
"indexBounds" : {
"user.age" : [
"[-inf.0, 10.0)"
]
},
"keysExamined" : 98716,
"seeks" : 1,
"dupsTested" : 0,
"dupsDropped" : 0,
"seenInvalidated" : 0
}
}
},
...

Notes: the IXSCAN stands for Index Scan. It means this stage is using one of the index on this collection. We can get the detailed index by looking at the “indexName” and “multiKeyPaths” fields.

From the output we can see that the returned document number is equal to examined key and examined document which means we don’t do any unnecessary query. The execution time is down to 87 milliseconds as well. For the execution stages, we can observe that there are two stages, an IXSCAN stage followed by a FETCH stage. IXSCAN returns 98716 document to FETCH which is the final returned document. This is a pretty good shape of query execution.

Let’s do a more complicated query.

db.users.explain('executionStats').find({"user.age":{$lt:10}, "user.name.last":"Lee"})
...
"executionStats" : {
"executionSuccess" : true,
"nReturned" : 2006,
"executionTimeMillis" : 102,
"totalKeysExamined" : 98716,
"totalDocsExamined" : 98716,
"executionStages" : {
"stage" : "FETCH",
"filter" : {
"user.name.last" : {
"$eq" : "Lee"
}
},
"nReturned" : 2006,
"executionTimeMillisEstimate" : 91,
"works" : 98717,
"advanced" : 2006,
"needTime" : 96710,
"needYield" : 0,
"saveState" : 771,
"restoreState" : 771,
"isEOF" : 1,
"invalidates" : 0,
"docsExamined" : 98716,
"alreadyHasObj" : 0,
"inputStage" : {
"stage" : "IXSCAN",
"nReturned" : 98716,
"executionTimeMillisEstimate" : 20,
"works" : 98717,
"advanced" : 98716,
"needTime" : 0,
"needYield" : 0,
"saveState" : 771,
"restoreState" : 771,
"isEOF" : 1,
"invalidates" : 0,
"keyPattern" : {
"user.age" : 1
},
"indexName" : "user.age_1",
"isMultiKey" : false,
"multiKeyPaths" : {
"user.age" : [ ]
},
"isUnique" : false,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 2,
"direction" : "forward",
"indexBounds" : {
"user.age" : [
"[-inf.0, 10.0)"
]
},
"keysExamined" : 98716,
"seeks" : 1,
"dupsTested" : 0,
"dupsDropped" : 0,
"seenInvalidated" : 0
}
}
},
...

The above code queries the users under 10 years old with “Lee” as last name. There are two stages as before but the number of document is quite different. The first stage “IXSCAN” returns the same document number as the previous query, 98716. But the second stage FETCH only returns 2006 documents but examined 98716 documents. This means there are 98716 users who is younger than 10 years old and 2006 of them has last name “Lee”. The total execution time for this query is 102 milliseconds. It uses the IXSCAN which is good but the second stage doesn’t seem a good shape. Now our task is to improve the second stage performance.

In order to do that the first idea would be to create an index on “user.name.last” field.

> db.users.createIndex({"user.name.last":1})
{
"createdCollectionAutomatically" : false,
"numIndexesBefore" : 3,
"numIndexesAfter" : 4,
"ok" : 1
}

Now try the same query:

> db.users.explain("executionStats").find({"user.age":{$lt:10}, "user.name.last":"Lee"})
...
},
"executionStats" : {
"executionSuccess" : true,
"nReturned" : 2006,
"executionTimeMillis" : 24,
"totalKeysExamined" : 20013,
"totalDocsExamined" : 20013,
"executionStages" : {
"stage" : "FETCH",
"filter" : {
"user.age" : {
"$lt" : 10
}
},
"nReturned" : 2006,
"executionTimeMillisEstimate" : 10,
...
"docsExamined" : 20013,
"alreadyHasObj" : 0,
"inputStage" : {
"stage" : "IXSCAN",
"nReturned" : 20013,
"executionTimeMillisEstimate" : 0,
...
"keyPattern" : {
"user.name.last" : 1
},
"indexName" : "user.name.last_1"
"isMultiKey" : false,
"multiKeyPaths" : {
"user.name.last" : [ ]
},
...

Still, we get two stages IXSCAN and FETCH, this time the IXSCAN is using “user.name.last” index returned 20013 documents (it is the number of users whose last name is “Lee”), while the FETCH returns 2006 document from it. Actually we get the same result as before and it doesn’t seem that this query is using both of the indexes we created. What is the problem then?

The reason is about how MongoDB using index to do that query. In our query we used two conditions: “user.age” and “user.name.last”. Let check our index:

> db.users.getIndexes()
[
{
"v" : 2,
"key" : {
"_id" : 1
},
"name" : "_id_",
"ns" : "template.users"
},
{
"v" : 2,
"key" : {
"user.name.first" : 1
},
"name" : "user.name.first_1",
"ns" : "template.users"
},
{
"v" : 2,
"key" : {
"user.age" : 1
},
"name" : "user.age_1",
"ns" : "template.users"
},
{
"v" : 2,
"key" : {
"user.name.last" : 1
},
"name" : "user.name.last_1",
"ns" : "template.users"
}
]

we have defined three indexes individually. But not combined indexes of “user.age” and “user.name.last”. Now let’s create this combined index and have a try:

> db.users.createIndex({"user.age":1, "user.name.last":1})
{
"createdCollectionAutomatically" : false,
"numIndexesBefore" : 4,
"numIndexesAfter" : 5,
"ok" : 1
}

then run the same query:

> db.users.explain("executionStats").find({"user.age":{$lt:10}, "user.name.last":"Lee"})
...
"executionStats" : {
"executionSuccess" : true,
"nReturned" : 2006,
"executionTimeMillis" : 5,
"totalKeysExamined" : 2027,
"totalDocsExamined" : 2006,
"executionStages" : {
"stage" : "FETCH",
"nReturned" : 2006,
"executionTimeMillisEstimate" : 11,
"works" : 2027,
"advanced" : 2006,
"needTime" : 20,
"needYield" : 0,
"saveState" : 19,
"restoreState" : 19,
"isEOF" : 1,
"invalidates" : 0,
"docsExamined" : 2006,
"alreadyHasObj" : 0,
"inputStage" : {
"stage" : "IXSCAN",
"nReturned" : 2006,
"executionTimeMillisEstimate" : 11,
"works" : 2027,
"advanced" : 2006,
"needTime" : 20,
"needYield" : 0,
"saveState" : 19,
"restoreState" : 19,
"isEOF" : 1,
"invalidates" : 0,
"keyPattern" : {
"user.age" : 1,
"user.name.last" : 1
},
"indexName" : "user.age_1_user.name.last_1",
"isMultiKey" : false,
"multiKeyPaths" : {
"user.age" : [ ],
"user.name.last" : [ ]
},
...

we can see this time the IXSCAN is using the index we just created which name is “user.age_1_user.name.last_1” and it returns 2006 documents that is also the total number of returned documents. The execution time is down to 5 milliseconds. Now we can conclude that we created the correct index for our query.

Let’s inspect a query which has multiple children stages in its explain.

db.users.explain("executionStats").find({$or: [{"user.name.last":"Lee"},{"user.name.first":"Lily"}]})
...
"executionStats" : {
"executionSuccess" : true,
"nReturned" : 32778,
"executionTimeMillis" : 34,
"totalKeysExamined" : 33017,
"totalDocsExamined" : 32778,
"executionStages" : {
"stage" : "SUBPLAN",
"nReturned" : 32778,
"executionTimeMillisEstimate" : 30,
"works" : 33019,
"advanced" : 32778,
"needTime" : 240,
"needYield" : 0,
"saveState" : 257,
"restoreState" : 257,
"isEOF" : 1,
"invalidates" : 0,
"inputStage" : {
"stage" : "FETCH",
"nReturned" : 32778,
"executionTimeMillisEstimate" : 30,
"works" : 33019,
"advanced" : 32778,
"needTime" : 240,
"needYield" : 0,
"saveState" : 257,
"restoreState" : 257,
"isEOF" : 1,
"invalidates" : 0,
"docsExamined" : 32778,
"alreadyHasObj" : 0,
"inputStage" : {
"stage" : "OR",
"nReturned" : 32778,
"executionTimeMillisEstimate" : 10,
"works" : 33019,
"advanced" : 32778,
"needTime" : 240,
"needYield" : 0,
"saveState" : 257,
"restoreState" : 257,
"isEOF" : 1,
"invalidates" : 0,
"dupsTested" : 33017,
"dupsDropped" : 239,
"recordIdsForgotten" : 0,
"inputStages" : [
{
"stage" : "IXSCAN",
"nReturned" : 13004,
"executionTimeMillisEstimate" : 0,
"works" : 13005,
"advanced" : 13004,
"needTime" : 0,
"needYield" : 0,
"saveState" : 257,
"restoreState" : 257,
"isEOF" : 1,
"invalidates" : 0,
"keyPattern" : {
"user.name.first" : 1
},
"indexName" : "user.name.first_1",
"isMultiKey" : false,
"multiKeyPaths" : {
"user.name.first" : [ ]
},
"isUnique" : false,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 2,
"direction" : "forward",
"indexBounds" : {
"user.name.first" : [
"[\"Lily\", \"Lily\"]"
]
},
"keysExamined" : 13004,
"seeks" : 1,
"dupsTested" : 0,
"dupsDropped" : 0,
"seenInvalidated" : 0
},
{
"stage" : "IXSCAN",
"nReturned" : 20013,
"executionTimeMillisEstimate" : 10,
"works" : 20014,
"advanced" : 20013,
"needTime" : 0,
"needYield" : 0,
"saveState" : 257,
"restoreState" : 257,
"isEOF" : 1,
"invalidates" : 0,
"keyPattern" : {
"user.name.last" : 1
},
"indexName" : "user.name.last_1",
"isMultiKey" : false,
"multiKeyPaths" : {
"user.name.last" : [ ]
},
"isUnique" : false,
"isSparse" : false,
"isPartial" : false,
"indexVersion" : 2,
"direction" : "forward",
"indexBounds" : {
"user.name.last" : [
"[\"Lee\", \"Lee\"]"
]
},
"keysExamined" : 20013,
"seeks" : 1,
"dupsTested" : 0,
"dupsDropped" : 0,
"seenInvalidated" : 0
}
]
}
}
}
},
...

The query tries to find the users whose last name is “Lee” or first name is “Lily”. Since both “user.name.last” and “user.name.first” are indexes in our collection. And we are using OR in the query. That why we see a “OR” stage on the explain output. Interestingly there are two IXSCAN stages under “OR” for the two query conditions. These two IXSCAN stages tell us there are 20013 users whose last name is “Lee” and 13004 users whose first name is “Lily”. While the total number of returned document is 32778. If we do a calculation on these numbers we found that

(13004 + 20013) - 32778 = 239

The number of returned documents from the two IXSCAN stages are greater than the total number of returned documents by 239 in this query. Where does this number come from? In oder to find out the reason let’s do below query:

> db.users.find({"user.name.last":"Lee", "user.name.first":"Lily"}).count()
239

there are 239 users whose last name is Lee and first name is Lily. That means both of the IXSCAN stages count this number. So the final result is 239 less than the total of these two stages.

After reviewing this article, I believe you understand how to use explain to inspect the query performance on MongoDB. In the next article, I am going to show you how to examine the query explain on a Shard cluster.


Like what you read? Give Zhao Yi a round of applause.

From a quick cheer to a standing ovation, clap to show how much you enjoyed this story.