0

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

  • explain.executionStats.executionTimeMillis is defined as "Total time in milliseconds required for query plan selection and query execution."; it may be the two actions's combined total. – prasad_ Mar 21 at 12:23
  • Thanks. But I don't anticipate the query plan selection to take any time at all. There were no rejected plans, so plan selection should be fast. Maybe the estimates are completely wrong, but that's what I'm trying to ascertain. – Rash-DBA Mar 23 at 9:52

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.