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

羅羅亞る索隆
  • 21

在慢查询日志里,根据索引查询一个表,返回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,
                ......

回复
阅读 1.6k
1 个回答

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

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

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

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

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

撰写回答
你尚未登录,登录后可以
  • 和开发者交流问题的细节
  • 关注并接收问题和回答的更新提醒
  • 参与内容的编辑和改进,让解决方法与时俱进
你知道吗?

宣传栏