关于MongoDB的慢查询日志的一些疑惑

Question

今天查询线上MongoDB的慢查询日志的时候 发现了一些问题

问题一
表总数是1007422 却看到这样的输出信息

keysExamined:4946620 docsExamined:1007409

怎么keysExamined可以超过总数吗？

问题二
查询数据 limit:50 应用日志输出的查询总数明明是50 但是MongoDB的日志却显示只有31条

nreturned:31 reslen:1122746

怎么MongoDB的日志不准吗？

---

补充

Java代码

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());

慢查询日志

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

应用日志

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

为什么MongoDB日志显示返回31条 但是应用日志却输出的是50条
并且奇怪的是 好像只有查出的正好是50条的时候 才会有对不上的情况 如果查询的数目小于50条能对的上 如

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

只有正好查出是50条 才会有不一致的情况 如下面的这个又不一致了

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:{ Global: { 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

但是也有MongoDB日志和应用都是50的情况 所以才让人弄不清楚是怎么回事

补充：
对不上的情况 似乎MongoDB和应用的日志会有3~4秒的差距

Answer 1

问题一
可能是数组上的索引，也就是Multikey Index。这是正常的。一个文档的数组有多少个元素就有多少个key。

问题二
如果符合条件的一共只有31条，不就是31了吗？

Answer 2

问题二的原因已经知道

应用日志

[2018-04-20T16:30:12,517+08:00] INFO  [extractScheduler-1] impl.MongoDataSourceServiceImpl - query count 23

MongoDB日志

2018-04-20T08:30:07.988+0000 I COMMAND  [conn346778] command foo.bar command: find ..., limit: 50, ... keysExamined:14417 docsExamined:7725 ... nreturned:16 reslen:1284323 ...
2018-04-20T08:30:12.445+0000 I COMMAND  [conn346778] command foo.bar command: getMore { getMore: 160602735017, collection: "bar" } ... keysExamined:158029 docsExamined:40333 nreturned:7 reslen:962387 ...

23 = 7 + 16

MongoDB分成两步来操作的 而getMore可能查询很快（小于100ms） 没有慢日志 导致误以为对不上