MongoDB Explain plan - elapsed time breakdown for executionStats

Hi all.
I’ve been running some performance/diagnostic tests, and need some help in understanding the mongodb explain plan, in specific, the execution stats.

I have run an explain plan for a query, and am a bit confused with the timings of each stage, and how they aggregate to the total elapsed time.

Following command was run to generate the statistics, verbosity mode set to executionStats Mode.

expStats = db.testdb.explain("executionStats")

expStats.aggregate([
    {"$match": {
        "Id": {"$in": ["AAA", "BBB"]},
        "testType":"TEST",
        }
    },
    {"$group": {
        "_id": {"Id":"$Id", "testType": "$testType", "testSubType":"$testSubType"},
        "count": {"$sum": 1}
        }
        }
    ])

A summary of the executionStats as follows:

"executionStats" : {
    "executionSuccess" : true,
    "nReturned" : 6355196,
    "executionTimeMillis" : 17575,
    "totalKeysExamined" : 6355196,
    "totalDocsExamined" : 0,
    "executionStages" : {
        "stage" : "PROJECTION_COVERED",
        "nReturned" : 6355196,
        "executionTimeMillisEstimate" : 3464,
        "works" : 6355197,
        "advanced" : 6355196,
        "needTime" : 0,
        "needYield" : 0,
        "saveState" : 50390,
        "restoreState" : 50390,
        "isEOF" : 1,
        "transformBy" : {
            "Id" : 1,
            "testSubType" : 1,
            "testType" : 1,
            "_id" : 0
        },
        "inputStage" : {
            "stage" : "IXSCAN",
            "nReturned" : 6355196,
            "executionTimeMillisEstimate" : 3251,
            "works" : 6355197,
            "advanced" : 6355196,
            "needTime" : 0,
            "needYield" : 0,
            "saveState" : 50390,
            "restoreState" : 50390,
            "isEOF" : 1,
            "keyPattern" : {
                        "Id" : 1,
                        "testType" : 1,
                        "eventTimestamp" : -1,
                        "testSubType" : 1
                },
                "indexName" : "clientEvents",
                "isMultiKey" : false,
                "multiKeyPaths" : {
                        "Id" : [ ],
                        "testType" : [ ],
                        "eventTimestamp" : [ ],
                        "testSubType" : [ ]
                },
                "isUnique" : false,
                "isSparse" : false,
                "isPartial" : false,
                "indexVersion" : 2,
                "direction" : "forward",
                "keysExamined" : 6355196,
                "seeks" : 1,
                "dupsTested" : 0,
                "dupsDropped" : 0
            }
        }
    }
},
{
"$group" : {
    "_id" : {
            "Id" : "$Id",
            "testType" : "$testType",
            "testSubType" : "$testSubType"
    },
    "count" : {
            "$sum" : {
                    "$const" : 1
            }
    }
}
}

The total execution time time = “executionTimeMillis” : 17575.

STAGE 1 (PROJECTION_COVERED) estimated execution time = “executionTimeMillisEstimate” : 3464.

STAGE 2 (IXSCAN) estimated execution time = “executionTimeMillisEstimate” : 3251.

So 6715 ms spent on the 2 STAGES.

Where was the remaining 10860 ms execution time spent? I cannot work it out, and the execution stats don’t tell me either

This is mongodb version 4.2, running on Linux

One of my frustrations with the Explain Plan documentation is its lack of precise information with regards certain fields and behaviours. For example, it doesn’t “explain” what this executionTimeMillisEstimate field means (and a host of others) and it also does not explain how the Explain Plan should be read for an aggregation pipeline.

My understanding of the executionTimeMillisEstimate is that (as the name implies) an “estimate”, probably based on the query planner or some cached stats. So there won’t be much of a correlation between the actual time (executionTimeMillis) and the estimate.

The execution stats you’re seeing is for the cursor stage (stages[0].$cursor) only, i.e. $match. The $group stage (stages[1].$group) is not accounted for in the executionTimeMillis or nReturned fields. Reporting execution stats on individual group stages has never existed in versions <=4.2.3 but (hopefully) will be included in the upcoming MongoDB release.