I found some problems when querying MongoDB’s slow query log online today.
Problem one
The total number of tables is1007422
But 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
Problem one
It may be an index on an array, that is, a Multikey Index. This is normal. There are as many keys as there are elements in an array of documents.question 2
If there are only 31 eligible ones, isn’t that 31?