2

I have a collection faults in my MongoDB database which every document has these fields: rack_name, timestamp

Just for sake of testing and comparing performances, I have created these two indexes:

rack -> {'rack_name': 1}

and

time -> {'timestamp': 1}

Now I executed the following query with explain():

db.faults.find({
    'rack_name': {
        $in: [ 'providence1', 'helena2' ]
    }, 
    'timestamp': {
        $gt: 1501548359000
    }
})
.explain('allPlansExecution') 

and here is the result:

 {
"queryPlanner" : {
    "plannerVersion" : 1,
    "namespace" : "quicktester_clone.faults",
    "indexFilterSet" : false,
    "parsedQuery" : {
        "$and" : [ 
            {
                "timestamp" : {
                    "$gt" : 1501548359000.0
                }
            }, 
            {
                "rack_name" : {
                    "$in" : [ 
                        "helena2", 
                        "providence1"
                    ]
                }
            }
        ]
    },
    "winningPlan" : {
        "stage" : "FETCH",
        "filter" : {
            "timestamp" : {
                "$gt" : 1501548359000.0
            }
        },
        "inputStage" : {
            "stage" : "IXSCAN",
            "keyPattern" : {
                "rack_name" : 1
            },
            "indexName" : "rack",
            "isMultiKey" : false,
            "multiKeyPaths" : {
                "rack_name" : []
            },
            "isUnique" : false,
            "isSparse" : false,
            "isPartial" : false,
            "indexVersion" : 2,
            "direction" : "forward",
            "indexBounds" : {
                "rack_name" : [ 
                    "[\"helena2\", \"helena2\"]", 
                    "[\"providence1\", \"providence1\"]"
                ]
            }
        }
    },
    "rejectedPlans" : [ 
        {
            "stage" : "FETCH",
            "filter" : {
                "rack_name" : {
                    "$in" : [ 
                        "helena2", 
                        "providence1"
                    ]
                }
            },
            "inputStage" : {
                "stage" : "IXSCAN",
                "keyPattern" : {
                    "timestamp" : 1
                },
                "indexName" : "time",
                "isMultiKey" : false,
                "multiKeyPaths" : {
                    "timestamp" : []
                },
                "isUnique" : false,
                "isSparse" : false,
                "isPartial" : false,
                "indexVersion" : 2,
                "direction" : "forward",
                "indexBounds" : {
                    "timestamp" : [ 
                        "(1501548359000.0, inf.0]"
                    ]
                }
            }
        }
    ]
},
"executionStats" : {
    "executionSuccess" : true,
    "nReturned" : 43,
    "executionTimeMillis" : 1512,
    "totalKeysExamined" : 221,
    "totalDocsExamined" : 219,
    "executionStages" : {
        "stage" : "FETCH",
        "filter" : {
            "timestamp" : {
                "$gt" : 1501548359000.0
            }
        },
        "nReturned" : 43,
        "executionTimeMillisEstimate" : 1431,
        "works" : 222,
        "advanced" : 43,
        "needTime" : 177,
        "needYield" : 0,
        "saveState" : 64,
        "restoreState" : 64,
        "isEOF" : 1,
        "invalidates" : 0,
        "docsExamined" : 219,
        "alreadyHasObj" : 0,
        "inputStage" : {
            "stage" : "IXSCAN",
            "nReturned" : 219,
            "executionTimeMillisEstimate" : 71,
            "works" : 221,
            "advanced" : 219,
            "needTime" : 1,
            "needYield" : 0,
            "saveState" : 64,
            "restoreState" : 64,
            "isEOF" : 1,
            "invalidates" : 0,
            "keyPattern" : {
                "rack_name" : 1
            },
            "indexName" : "rack",
            "isMultiKey" : false,
            "multiKeyPaths" : {
                "rack_name" : []
            },
            "isUnique" : false,
            "isSparse" : false,
            "isPartial" : false,
            "indexVersion" : 2,
            "direction" : "forward",
            "indexBounds" : {
                "rack_name" : [ 
                    "[\"helena2\", \"helena2\"]", 
                    "[\"providence1\", \"providence1\"]"
                ]
            },
            "keysExamined" : 221,
            "seeks" : 2,
            "dupsTested" : 0,
            "dupsDropped" : 0,
            "seenInvalidated" : 0
        }
    },
    "allPlansExecution" : [ 
        {
            "nReturned" : 2,
            "executionTimeMillisEstimate" : 31,
            "totalKeysExamined" : 221,
            "totalDocsExamined" : 221,
            "executionStages" : {
                "stage" : "FETCH",
                "filter" : {
                    "rack_name" : {
                        "$in" : [ 
                            "helena2", 
                            "providence1"
                        ]
                    }
                },
                "nReturned" : 2,
                "executionTimeMillisEstimate" : 31,
                "works" : 221,
                "advanced" : 2,
                "needTime" : 219,
                "needYield" : 0,
                "saveState" : 64,
                "restoreState" : 64,
                "isEOF" : 0,
                "invalidates" : 0,
                "docsExamined" : 221,
                "alreadyHasObj" : 0,
                "inputStage" : {
                    "stage" : "IXSCAN",
                    "nReturned" : 221,
                    "executionTimeMillisEstimate" : 10,
                    "works" : 221,
                    "advanced" : 221,
                    "needTime" : 0,
                    "needYield" : 0,
                    "saveState" : 64,
                    "restoreState" : 64,
                    "isEOF" : 0,
                    "invalidates" : 0,
                    "keyPattern" : {
                        "timestamp" : 1
                    },
                    "indexName" : "time",
                    "isMultiKey" : false,
                    "multiKeyPaths" : {
                        "timestamp" : []
                    },
                    "isUnique" : false,
                    "isSparse" : false,
                    "isPartial" : false,
                    "indexVersion" : 2,
                    "direction" : "forward",
                    "indexBounds" : {
                        "timestamp" : [ 
                            "(1501548359000.0, inf.0]"
                        ]
                    },
                    "keysExamined" : 221,
                    "seeks" : 1,
                    "dupsTested" : 0,
                    "dupsDropped" : 0,
                    "seenInvalidated" : 0
                }
            }
        }, 
        {
            "nReturned" : 43,
            "executionTimeMillisEstimate" : 1431,
            "totalKeysExamined" : 221,
            "totalDocsExamined" : 219,
            "executionStages" : {
                "stage" : "FETCH",
                "filter" : {
                    "timestamp" : {
                        "$gt" : 1501548359000.0
                    }
                },
                "nReturned" : 43,
                "executionTimeMillisEstimate" : 1431,
                "works" : 221,
                "advanced" : 43,
                "needTime" : 177,
                "needYield" : 0,
                "saveState" : 64,
                "restoreState" : 64,
                "isEOF" : 1,
                "invalidates" : 0,
                "docsExamined" : 219,
                "alreadyHasObj" : 0,
                "inputStage" : {
                    "stage" : "IXSCAN",
                    "nReturned" : 219,
                    "executionTimeMillisEstimate" : 71,
                    "works" : 221,
                    "advanced" : 219,
                    "needTime" : 1,
                    "needYield" : 0,
                    "saveState" : 64,
                    "restoreState" : 64,
                    "isEOF" : 1,
                    "invalidates" : 0,
                    "keyPattern" : {
                        "rack_name" : 1
                    },
                    "indexName" : "rack",
                    "isMultiKey" : false,
                    "multiKeyPaths" : {
                        "rack_name" : []
                    },
                    "isUnique" : false,
                    "isSparse" : false,
                    "isPartial" : false,
                    "indexVersion" : 2,
                    "direction" : "forward",
                    "indexBounds" : {
                        "rack_name" : [ 
                            "[\"helena2\", \"helena2\"]", 
                            "[\"providence1\", \"providence1\"]"
                        ]
                    },
                    "keysExamined" : 221,
                    "seeks" : 2,
                    "dupsTested" : 0,
                    "dupsDropped" : 0,
                    "seenInvalidated" : 0
                }
            }
        }
    ]
},
"serverInfo" : {
    "host" : "dtauto-sna01.mascorp.com",
    "port" : 27017,
    "version" : "3.4.4",
    "gitVersion" : "888390515874a9debd1b6c5d36559ca86b44babd"
},
"ok" : 1.0
}

Two things I do not understand:

  1. When you look at AllPlansExecution the nReturned key has different value on each plan. Second plan (index: rack) is actually the winner plan and returns 43 results which is the actual return result of the whole query, but what are those 2 nReturned result from the first

  2. More challenge comes to this point that why the first plan (index: time which is the rejected plan) has been reported with less executionTimeMillis value 31 than the winner plan executionTimeMillis 1431?

What's going on?

3
  • Would it not be a big hint that if you reduced the $in to just "one" condition instead of "two" then what would the results look like then? Consider that "if you were a database, how would you determine which is best when you decide to fetch something?" Would you not try the "alternatives" before deciding which to choose? Does that "trying" possibly return a number of results?
    – Neil Lunn
    Aug 4, 2017 at 2:51
  • I get what you say but according to dba86.com/docs/mongo/2.4/core/query-plans.html apparently they do not necessarily match, but still I cannot explain the scenario. So I removed 'helena2', nReturned value turned into 1 (from 2) on the first plan and 17 (from 43) for on the second plan. Aug 4, 2017 at 2:59
  • Then how can you still be asking "where does the 2 come from?". Because you just did the relevant test that shows you exactly where it comes from. Please note that there are in fact the verbose stats from explain output not really that relevant to the overall tuning of query performance. The basic premise i was explaining to you is that "in order to choose something, you must first do something". Hence the stats you are referring to are in fact related to exactly that point, and not really anything to do with the result set itself.
    – Neil Lunn
    Aug 4, 2017 at 3:41

1 Answer 1

6

This was explained in the allPlansExecution Mode documentation page. To paraphrase:

MongoDB runs the query optimizer to choose the winning plan and executes the winning plan to completion. In "allPlansExecution" mode, MongoDB returns statistics describing the execution of the winning plan as well as statistics for the other candidate plans captured during plan selection.

During plan selection, if there are more than one index that can satisfy a query, MongoDB will run a trial using all the valid plans to determine which one performed to be the best. See Query Plans for details regarding this process.

As of MongoDB 3.4.6, the plan selection involves running candidate plans in parallel in a "race", and see which candidate plan returns 101 results first. In your example above, by the time the winning plan returned 101 results in the race, the losing plan managed only 2 results. The winning plan then gets executed to completion. This is the reason why the losing plan shows only nReturned: 2 in the stats.

This "race" is performed since if there are two identical-looking plans, MongoDB doesn't know which plan is the best for a particular query due to the flexibility of JSON documents (unlike e.g. SQL where the structure of the tables are known). Of course, it is entirely possible that MongoDB guesses wrong, and end up with a less than performant plan, since it is an empirical process. For this reason, it's best to create indexes that supports your queries so MongoDB doesn't have to guess. Otherwise, you can use hint() to tell MongoDB which index to use for a certain query.

Hence:

  • The statistics for the winning plan is the actual query's result statistics.
  • The statistics for the losing plan(s) only shows the statistics for the query planning trial run.
  • The plan selection involves running a "race" to 101 results. This race is only performed when there are multiple indexes that can satisfy the query.

Note 1: Neither of the two plans you saw were great. The winning plan shows "nReturned" : 43, "totalKeysExamined" : 221, and "totalDocsExamined" : 219. This means that MongoDB needs to examine 219 documents only to return 43 of them: only 20% efficiency. Ideally, you want to have the nReturned numbers equal to totalDocsExamined.

Note 2: Try creating the compound index {'rack_name': 1, 'timestamp': 1}. With the same query, you should get a better efficiency number.

Note 3: Note that since allPlansExecution was specified, all statistics is duly returned to you by MongoDB for thoroughness, while it has no bearing whatsoever to the final nReturned result. It was a rejected plan, and the nReturned: 2 number can be confusing. You won't see this statistics if you use executionStats setting. Primarily, the allPlansExecution is used for fine-tuning and determining why some plans are rejected.

2
  • 1
    Actually I know {'rack_name':1, 'timestamp':1} would be most efficient, but I am trying to understand mongoDB. My question is what does it mean "losing plan only managed to generate 2 results"? I mean how winning plan could get ahead of the loosing plan? because on all stages you see the loosing plan had less executionTimeMillisEstimate. I mean how you explain the scenario of the winning plan getting ahead of the loosing plan on returning all the results? Aug 4, 2017 at 18:12
  • Is a candidate plan still chosen with the same criteria (101 results first) in MongoDB versions 4.x? Im asking because the documentation reports the 101 results only in MongoDB v 2.x versions. Nov 5, 2020 at 18:49

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge that you have read and understand our privacy policy and code of conduct.

Not the answer you're looking for? Browse other questions tagged or ask your own question.