Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-17332

getmore/query logging/profiling should indicate cursor exhaustion

    • Type: Icon: Improvement Improvement
    • Resolution: Done
    • Priority: Icon: Minor - P4 Minor - P4
    • 3.1.2
    • Affects Version/s: None
    • Component/s: Logging, Querying
    • Labels:
    • Minor Change
    • Quint Iteration 3.1.2

      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.

            Assignee:
            james.wahlin@mongodb.com James Wahlin
            Reporter:
            kevin.pulo@mongodb.com Kevin Pulo
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

              Created:
              Updated:
              Resolved: