mongodb中profile的执行时间millis和explain的为什么不一样？

Question

在慢查询日志里，根据索引查询一个表，返回0条数据，millis显示耗时200ms以上，但每个执行阶段的executionTimeMillisEstimate都是0.
单独模仿这条查询记录在shell里查询，exlpain执行计划显示耗时0ms.
所以为什么在慢查询日志里，明明压根没找到数据，却耗时那么久？

{
    "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,
                ......

Answer 1

从名字就看出来了，executionTimeMillisEstimate之所以叫做"estimate"就是因为它只是个估计值，跟真实值有出入是正常的。不过你的值出入过大了，原因在于：

"$readPreference" : {
    "mode" : "secondaryPreferred"
}

从节点读的时候会受到replication的影响。为了保证效率，数据复制时总是一批数据一起往数据库中写，这就会存在一个问题，如果有些数据写成功了，另外一些还没写成功，谁成功谁没成功是会随机出现的，这样的中间状态在主节点上从来没存在过，它就不是最终一致的。为了避免这样的中间状态被读取到，MongoDB采取了一个极端的策略——全局锁。在一批数据完全写入从节点前，总是占用一个全局锁避免中间态被人读取到。而这个锁会占用多久，完全取决于你的磁盘能力。就你现在的情况来看，全局锁占用了约219ms：

"timeAcquiringMicros" : {
    "r" : NumberLong(219017)
}

总时间消耗是252ms，也就是说执行查询实际消耗了33ms。