I found some problems when querying MongoDB’s slow query log online today.

Problem one
The total number of tables is1007422But see such output information

keysExamined:4946620 docsExamined:1007409

How can keysExamined exceed the total?

question 2
Query Data limit:50 The total number of queries output from the application log is obviously 50, but MongoDB’s log shows only 31

nreturned:31 reslen:1122746

What, MongoDB’s log is not allowed?

supplement

Java code

MongoCursor<Document> cursor = collection.find(queryDocument)
 .projection(new Document(XXX, 1))
 .limit(50)
 .iterator();
 List<Document> list = new ArrayList<>();
 while (cursor.hasNext()) {
 Document document = cursor.next();
 //  ...
 list.add(document);
 }
 logger.info("query count: {}", list.size());

Slow query log

2018-04-18T10:38:34.540+0000 I COMMAND  [conn307438] command foo.bar command: find ..., limit: 50, shardVersion: [ Timestamp 0|0,   ObjectId('000000000000000000000000') ] } planSummary: IXSCAN { created_at: -1.0 }   cursorid:156438606875 keysExamined:68 docsExamined:68 fromMultiPlanner:1 keyUpdates:0 writeConflicts:0 numYields:9 nreturned:31 reslen:1122746 locks:{   Global: { acquireCount: { r: 20 } }, Database: { acquireCount: { r: 10 } }, Collection: { acquireCount: { r: 10 } } } protocol:op_command 115ms

Application log

[2018-04-18T18:38:37,446+08:00] INFO  [http-nio-8080-exec-4] impl.MongoDataSourceServiceImpl - query count: 50

Why does MongoDB log show that it returns 31 but the application log outputs 50
And strangely, it seems that only when exactly 50 items are found can there be mismatches if the number of queries is less than 50 items

2018-04-18T10:54:44.635+0000 I COMMAND  [conn307262] command foo.bar command: find ..., limit: 50, shardVersion: [ Timestamp 0|0,   ObjectId('000000000000000000000000') ] } planSummary: IXSCAN { create_at: -1.0,   xxx: -1.0 }   keysExamined:4946661 docsExamined:1007422 fromMultiPlanner:1 replanned:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:87908 nreturned:14   reslen:136050 locks:{ Global: { acquireCount: { r: 175818 } }, Database: { acquireCount: { r: 87909 }, acquireWaitCount: { r: 6 },   timeAcquiringMicros: { r: 148774 } }, Collection: { acquireCount: { r: 87909 } } } protocol:op_command 967269ms
 [2018-04-18T18:54:44,935+08:00] INFO  [http-nio-8080-exec-4] impl.MongoDataSourceServiceImpl - query count: 14

Only when exactly 50 articles are found can there be inconsistencies, such as the following one

2018-04-18T11:32:45.426+0000 I COMMAND  [conn308123] command foo.bar command: find ..., limit: 50, shardVersion: [ Timestamp 0|0,   ObjectId('000000000000000000000000') ] } planSummary: IXSCAN { xxx: -1.0, xxx: -1.0, xxx: -1.0,   xxx: -1.0 }   cursorid:155252471899 keysExamined:2770867 docsExamined:395789 keyUpdates:0 writeConflicts:0 numYields:24185 nreturned:12 reslen:1116144 locks:{ Globa  l: { acquireCount: { r: 48372 } }, Database: { acquireCount: { r: 24186 } }, Collection: { acquireCount: { r: 24186 } } } protocol:op_command 154088ms
 ][2018-04-18T19:32:49,766+08:00] INFO  [http-nio-8080-exec-4] impl.MongoDataSourceServiceImpl - query count: 50

However, there are also cases where MongoDB logs and applications are both 50, which makes it unclear what is going on.

Add:
It seems that MongoDB will have a 3~4 second gap with the application log when it fails