[SERVER-25657] Inconsistent getMore logging Created: 17/Aug/16  Updated: 06/Dec/22  Resolved: 18/Aug/16

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

Type: Improvement Priority: Major - P3
Reporter: Dmitry Ryabtsev Assignee: Backlog - Query Team (Inactive)
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
duplicates SERVER-17862 Unify stats reporting for log/profile... Closed
Assigned Teams:
Query
Participants:

 Description   

As of 3.2.8 I can see at least three different types of getMore commands that can be logged:

"getMore on an aggregation cursor"

2016-08-17T05:30:55.215+0000 I COMMAND  [conn117464] getmore test.col query: { aggregate: "col", pipeline: [], fromRouter: true, cursor: { batchSize: 0 } } cursorid:4426089
5558 ntoreturn:0 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:3 nreturned:406 reslen:13418 locks:{ Global: { acquireCount: { r: 12 } }, Database: { acquireCoun
t: { r: 6 } }, Collection: { acquireCount: { r: 6 } } } 126ms

"getMore on a regular query"

2016-08-15T14:42:12.291-0400 I COMMAND  [conn616] getmore NAD.products cursorid:64166768643 ntoreturn:0 exhaust:1 keyUpdates:0 writeConflicts:0 numYields:5 nreturned:731 reslen:4197830 locks:{ Global: { acquireCount: { r: 12 } }, Database: { acquireCount: { r: 6 } }, Collection: { acquireCount: { r: 6 } } } 16ms

"getMore on a tailable cursor"

2016-08-15T16:25:01.642-0400 I COMMAND  [conn9] command local.oplog.rs command: getMore { getMore: 19848245430, collection: "oplog.rs", maxTimeMS: 5000, term: 1, lastKnownCommittedOpTime: { ts: Timestamp 1471286528000|1, t: 1 } } cursorid:19848245430 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:0 reslen:404 locks:{ Global: { acquireCount: { r: 6 } }, Database: { acquireCount: { r: 3 } }, oplog: { acquireCount: { r: 3 } } } protocol:op_command 5012ms

Note that the message format is different for each type. I believe this has to be made consistent/unified as part of SERVER-17862. If this has been taken care of already, please feel free to close.



 Comments   
Comment by Dmitry Ryabtsev [ 18/Aug/16 ]

I went ahead and tested v3.3.11 and the log messages are now consistent:

"3.3.11"

2016-08-17T20:27:40.779-0400 I COMMAND  [conn1] command test.col command: getMore { getMore: 27655847706, collection: "col" } originatingCommand: { aggregate: "col", pipeline: [ { $match: {} } ], cursor: {} } planSummary: COLLSCAN cursorid:27655847706 keysExamined:0 docsExamined:0 cursorExhausted:1 numYields:0 nreturned:32932 reslen:1306250 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } protocol:op_command 12ms
 
2016-08-17T20:28:25.963-0400 I COMMAND  [conn1] command test.col command: getMore { getMore: 28774893145, collection: "col" } originatingCommand: { find: "col", filter: {} } planSummary: COLLSCAN cursorid:28774893145 keysExamined:0 docsExamined:32932 cursorExhausted:1 numYields:257 nreturned:32932 reslen:1306250 locks:{ Global: { acquireCount: { r: 516 } }, Database: { acquireCount: { r: 258 } }, Collection: { acquireCount: { r: 258 } } } protocol:op_command 6ms
 
2016-08-17T20:34:29.429-0400 I COMMAND  [conn1] command test.log command: getMore { getMore: 31713681653, collection: "log" } originatingCommand: { find: "log", filter: {}, tailable: true, awaitData: true } planSummary: COLLSCAN cursorid:31713681653 keysExamined:0 docsExamined:0 numYields:1 nreturned:0 reslen:80 locks:{ Global: { acquireCount: { r: 6 } }, Database: { acquireCount: { r: 3 } }, Collection: { acquireCount: { r: 3 } } } protocol:op_command 1000ms

Thus closing this ticket as Duplicate.

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