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

  mongodb, question

In the slow query log, a table is queried according to the index, and 0 pieces of data are returned. millis shows that it takes more than 200ms, but the executionTimeMillisEstimate in each execution phase is 0.
Imitate this query record and query in the shell. exlpain execution plan takes 0 ms.
So why does it take so long to find data in the slow query log when there is no data 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,
 ......

As can be seen from the name,executionTimeMillisEstimateThe reason why it is called “estimate” is that it is only an estimate, and it is normal for it to differ from the real value. However, your values differ too much because:

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

Reading from a node is affected by replication. In order to ensure efficiency, when copying data, a batch of data is always written into the database together, which will lead to a problem. If some data are successfully written and others are not successfully written, whoever is successful and who is not will appear randomly. Such an intermediate state has never existed on the master node, and it is not final and consistent. In order to prevent such intermediate state from being read, MongoDB adopts an extreme strategy-global lock. Before a batch of data is completely written to the slave node, it always occupies a global lock to prevent the intermediate state from being read. How long this lock will last depends entirely on your disk capacity. According to your current situation, the global lock takes about 219ms:

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

The total time consumption is 252ms, that is to say, it actually takes 33ms to execute the query.