[SERVER-28423] Log file says nreturned is 0 when it cannot be 0 Created: 22/Mar/17  Updated: 17/Apr/17  Resolved: 22/Mar/17

Status: Closed
Project: Core Server
Component/s: Logging
Affects Version/s: 3.2.12
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Ahmed Nasser Assignee: James Wahlin
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Operating System: ALL
Participants:

 Description   

I have this line in the log file as a slow query:

2017-03-20T08:01:20.414+0000 I COMMAND [conn2424] command jidariDevDB.people_you_may_know command: find { find: "people_you_may_know", filter: { User: ObjectId('57042936377c2e29146b6386'), SuggestedUser: ObjectId('565d3e3b367c2ea030e016d5') }, projection: { Metadata: 1, Source: 1, Unread: 1, LastUpdated: 1, Points: 1 }, limit: 1, batchSize: 0, shardVersion: [ Timestamp 0|0, ObjectId('000000000000000000000000') ] } planSummary: IXSCAN { SuggestedUser: 1.0, User: 1.0 } cursorid:325486549227 keysExamined:1 docsExamined:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:0 reslen:234 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_command 886ms

As we can see the query is indexed and the keys exist and the document exists since "keysExamined:1 docsExamined:1".

My question is how nreturned is 0? Should not nreturned be 1?

I have also verified this by:

db.people_you_may_know.find({ User: ObjectId('57042936377c2e29146b6386'), SuggestedUser: ObjectId('565d3e3b367c2ea030e016d5') }, { Metadata: 1, Source: 1, Unread: 1, LastUpdated: 1, Points: 1 }).explain("executionStats")

and got:

"executionStats" : {
		"executionSuccess" : true,
		"nReturned" : 1,
		"executionTimeMillis" : 280,
		"totalKeysExamined" : 1,
		"totalDocsExamined" : 1,

Why does the log file report that nreturned = 0?



 Comments   
Comment by Ahmed Nasser [ 22/Mar/17 ]

Thanks James. That was very helpful. Please feel free to close the issue.

Comment by James Wahlin [ 22/Mar/17 ]

Hi Ahmed,

The only way to determine the number of documents that an indexed query with a filter would iterate over would be to perform a count operation. This operation will have to iterate over the index entries so comes with a cost.

If your find commands are always executed with a batchSize of 0, you can use the log entries for the subsequent getMore operations to capture nscanned/nreturned statistics.

Thanks,
James

Comment by Ahmed Nasser [ 22/Mar/17 ]

Any way to find out the number of documents in the result the cursor will iterate on?

Comment by Ahmed Nasser [ 22/Mar/17 ]

Thank you James. This was enlightening.

I believe this means that nreturned in the log file cannot be relied upon in determining the nscanned/nreturned ratio. Specially if the driver in use defaults batchSize to 0 as in my case.

Comment by James Wahlin [ 22/Mar/17 ]

Hi Ahmed,

The slow query you posted above shows that it was run with batchSize: 0. When a query is run with a batchSize of 0, it is requesting that no results be returned. Only a cursorid is returned, which can then be used to iterate over the results. Given that nreturned:0 is what you would expect to see.

Best regards,
James

Generated at Thu Feb 08 04:18:05 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.