Why is the execution time of profile in mongodb different from that of explain?

in the slow log, a table is queried according to the index and 0 items of data are returned. Millis shows that it takes more than 200ms, but the executionTimeMillisEstimate of each execution phase is 0.
imitates this query record to query in shell, and the exlpain execution plan shows that it takes 0 Ms.
so why does it take so long in the slow log when no data is found at all?

{
    "op" : "query",
    "ns" : "xxx",
    "command" : {
        "find" : "xxx",
        "filter" : {
            "type" : {
                "$exists" : false
            },
            "id" : "198006886"
        },
        "sort" : {
            "_id" : -1
        },
        "projection" : {
            "mmm" : 1,
            "_id" : 0
        },
        "$readPreference" : {
            "mode" : "secondaryPreferred"
        },
        "$db" : "xxx"
    },
    "keysExamined" : 0,
    "docsExamined" : 0,
    "hasSortStage" : true,
    "cursorExhausted" : true,
    "numYield" : 0,
    "locks" : {
        "Global" : {
            "acquireCount" : {
                "r" : NumberLong(2)
            },
            "acquireWaitCount" : {
                "r" : NumberLong(1)
            },
            "timeAcquiringMicros" : {
                "r" : NumberLong(219017)
            }
        },
        "Database" : {
            "acquireCount" : {
                "r" : NumberLong(1)
            }
        },
        "Collection" : {
            "acquireCount" : {
                "r" : NumberLong(1)
            }
        }
    },
    "nreturned" : 0,
    "responseLength" : 234,
    "protocol" : "op_query",
    "millis" : 252,
    "planSummary" : "IXSCAN { id: -1, mmm: -1 }",
    "execStats" : {
        "stage" : "CACHED_PLAN",
        "nReturned" : 0,
        "executionTimeMillisEstimate" : 0,
        "works" : 1,
        "advanced" : 0,
        "needTime" : 0,
        "needYield" : 0,
        "saveState" : 0,
        "restoreState" : 0,
        "isEOF" : 1,
        "invalidates" : 0,
        "inputStage" : {
            "stage" : "PROJECTION",
            "nReturned" : 0,
            "executionTimeMillisEstimate" : 0,
            "works" : 3,
            "advanced" : 0,
            "needTime" : 2,
            "needYield" : 0,
            "saveState" : 0,
            "restoreState" : 0,
            "isEOF" : 1,
            "invalidates" : 0,
            "transformBy" : {
                "id" : 1,
                "_id" : 0
            },
            "inputStage" : {
                "stage" : "SORT",
                "nReturned" : 0,
                "executionTimeMillisEstimate" : 0,
                ......

Dec.29,2021

from the name, executionTimeMillisEstimate is called "estimate" because it is only an estimate, and it is normal to differ from the real value. However, your value difference is too large, the reason is:

"timeAcquiringMicros" : {
    "r" : NumberLong(219017)
}
The total time consumption of

is 252ms, which means that executing the query actually consumes 33ms.

Menu