[SERVER-17332] getmore/query logging/profiling should indicate cursor exhaustion Created: 20/Feb/15  Updated: 28/Sep/16  Resolved: 13/Apr/15

Status: Closed
Project: Core Server
Component/s: Logging, Querying
Affects Version/s: None
Fix Version/s: 3.1.2

Type: Improvement Priority: Minor - P4
Reporter: Kevin Pulo Assignee: James Wahlin
Resolution: Done Votes: 0
Labels: neweng
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Documented
is documented by DOCS-8982 getmore/query logging/profiling shoul... Closed
Backwards Compatibility: Minor Change
Sprint: Quint Iteration 3.1.2
Participants:

 Description   

When getmores are logged (logLevel >= 1) or profiled, there should be an indication of whether or not the cursor has been exhausted.

If a batch size has been specified, then it is possible to infer exhaustion by checking if nreturned < ntoreturn:

db.test.drop()
for(i = 0; i < 20; i++) db.test.insert({})
db.test.find().batchSize(5).itcount()

2015-02-20T12:58:59.778+1100 I QUERY    [conn3] query test.test planSummary: COLLSCAN cursorid:31845874682 ntoreturn:5 ntoskip:0 nscanned:0 nscannedObjects:5 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:5 reslen:130 locks:{} 0ms
2015-02-20T12:58:59.778+1100 I QUERY    [conn3] getmore test.test cursorid:31845874682 ntoreturn:5 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:5 reslen:130 locks:{} 0ms
2015-02-20T12:58:59.778+1100 I QUERY    [conn3] getmore test.test cursorid:31845874682 ntoreturn:5 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:5 reslen:130 locks:{} 0ms
2015-02-20T12:58:59.779+1100 I QUERY    [conn3] getmore test.test cursorid:31845874682 ntoreturn:5 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:5 reslen:130 locks:{} 0ms
2015-02-20T12:58:59.779+1100 I QUERY    [conn3] getmore test.test cursorid:31845874682 ntoreturn:5 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:0 reslen:20 locks:{} 0ms

(system.profile has the same info as these log lines, of course.)

However without a batch size, ntoreturn will be 0, and so this isn't possible:

db.test.drop()
for(i = 0; i < 80; i++) db.test.insert({a: (new Array(102401)).join("x")})  // ~8MB of data
db.test.find().batchSize(0).itcount()

2015-02-20T13:01:57.962+1100 I QUERY    [conn3] query test.test planSummary: COLLSCAN cursorid:35502768857 ntoreturn:0 ntoskip:0 nscanned:0 nscannedObjects:11 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:11 reslen:1126750 locks:{} 0ms
2015-02-20T13:01:57.969+1100 I QUERY    [conn3] getmore test.test cursorid:35502768857 ntoreturn:0 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:41 reslen:4199650 locks:{} 4ms
2015-02-20T13:01:57.975+1100 I QUERY    [conn3] getmore test.test cursorid:35502768857 ntoreturn:0 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:28 reslen:2868060 locks:{} 0ms

There is nothing to distinguish these two getmores, however the second one is a more significant event because the cursor is known to have been exhausted and closed (meaning the cursorid is no longer valid and attempts to reuse it will cause an error).

It would be better the final getmore included something like exhausted:1 or eof:1.

(There's no need for anything like this for queries that return all results in the first batch - the absence of the cursorid:... field in those query log lines/profile documents indicates this. (SERVER-5871))

For consistency and clarity, the query operation should include the cursorExhausted flag as well.



 Comments   
Comment by Githook User [ 13/Apr/15 ]

Author:

{u'name': u'James Wahlin', u'email': u'james.wahlin@10gen.com'}

Message: SERVER-17332 Add cursorExhausted flag to find/getMore log/prof
Branch: master
https://github.com/mongodb/mongo/commit/5cfd95b0eb36c72f1b1b131ff1de76fe05f16cc3

Comment by J Rassi [ 01/Apr/15 ]

The breakdown of work for this ticket is as follows:

  • Add a boolean field to OpDebug with initial an value of false. Suggested name "cursorClosed" or "cursorExhausted" (let's leave the final naming decision to Dan).
  • Update OpDebug::report() and OpDebug::append() to read the value of this flag.
  • Update the getMore() function (find.cpp) and GetMoreCmd::run() (getmore_cmd.cpp) to set the value of this flag to true on the OpDebug object associated with the current OperationContext.
  • Add a getmore test to profile4.js which verifies that the profile document for a getMore operation has the correct value of the flag.
Generated at Thu Feb 08 03:44:03 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.