some problems were found when querying the slow query log of online MongoDB today
question 1
the total number of tables is 1007422 but you see this output
keysExamined:4946620 docsExamined:1007409how can keysExamined exceed the total?
question 2
query data the total number of queries output from the limit:50 application log is obviously 50, but the MongoDB log shows only 31 queries
nreturned:31 reslen:1122746
Why, is MongoDB"s log not correct?
< hr >add
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 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 115msApplication log
[2018-04-18T18:38:37,446+08:00] INFO [http-nio-8080-exec-4] impl.MongoDataSourceServiceImpl - query count: 50 Why the MongoDB log shows that 31 entries are returned, but the application log outputs 50
, and the strange thing is that there seems to be a mismatch only if the number of queries is less than 50, such as
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: 14there will be inconsistencies only if 50 items are found out, for example, the following one is inconsistent
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: 50but there are situations where MongoDB logs and applications are both 50, so people don"t know what"s going on
. add:
in the case of mismatch, it seems that there will be a gap of 3-4 seconds between the MongoDB and the application log