關(guān)于MongoDB的慢查詢?nèi)罩镜囊恍┮苫?/h1>

今天查詢線上MongoDB的慢查詢?nèi)罩镜臅r(shí)候 發(fā)現(xiàn)了一些問(wèn)題

問(wèn)題一
表總數(shù)是1007422 卻看到這樣的輸出信息

keysExamined:4946620 docsExamined:1007409

怎么keysExamined可以超過(guò)總數(shù)嗎？

問(wèn)題二
查詢數(shù)據(jù) limit:50 應(yīng)用日志輸出的查詢總數(shù)明明是50 但是MongoDB的日志卻顯示只有31條

nreturned:31 reslen:1122746

怎么MongoDB的日志不準(zhǔn)嗎？

---

補(bǔ)充

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

慢查詢?nèi)罩?/p>

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

應(yīng)用日志

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

為什么MongoDB日志顯示返回31條 但是應(yīng)用日志卻輸出的是50條
并且奇怪的是 好像只有查出的正好是50條的時(shí)候 才會(huì)有對(duì)不上的情況 如果查詢的數(shù)目小于50條能對(duì)的上 如

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條 才會(huì)有不一致的情況 如下面的這個(gè)又不一致了

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日志和應(yīng)用都是50的情況 所以才讓人弄不清楚是怎么回事

補(bǔ)充：
對(duì)不上的情況 似乎MongoDB和應(yīng)用的日志會(huì)有3~4秒的差距