[SERVER-19568] Diagnostic log operation entry format for find/getMore commands Created: 23/Jul/15  Updated: 07/Oct/15  Resolved: 23/Sep/15

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

Type: Improvement Priority: Major - P3
Reporter: J Rassi Assignee: David Storch
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Documented
is documented by DOCS-6259 Doc changes to query log entries for ... Closed
Duplicate
is duplicated by SERVER-20107 Update query log line format for find... Closed
Backwards Compatibility: Fully Compatible
Sprint: QuInt A (10/12/15)
Participants:

 Description   

The format of the query log line will differ based on whether the query was delivered using the 3.0-and-earlier OP_QUERY/OP_GET_MORE find protocol or using the find/getMore commands. Consider the following example query:

db.collection.find({a: {$gt: 3}}, {_id: 0, a: 1, b: 1}).sort({b: 1}).skip(11).limit(12);

If this query is delivered to a version 3.2 mongod using OP_QUERY/OP_GET_MORE wire protocol reads, the resulting log line will look something like this:

2015-09-23T14:39:21.452-0400 I QUERY    [conn1] query test.collection query: { query: { a: { $gt: 3.0 } }, orderby: { b: 1.0 } } planSummary: COLLSCAN, COLLSCAN ntoreturn:12 ntoskip:11 keysExamined:0 docsExamined:4 hasSortStage:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:0 reslen:20 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } 0ms

In contrast, if the query is delivered to a version 3.2 mongod using the find command, the log line will be:

2015-09-23T14:40:21.901-0400 I COMMAND  [conn2] command test.collection command: find { find: "collection", filter: { a: { $gt: 3.0 } }, skip: 11.0, limit: 12.0, singleBatch: false, sort: { b: 1.0 }, projection: { _id: 0.0, a: 1.0, b: 1.0 } } planSummary: COLLSCAN keysExamined:0 docsExamined:2 hasSortStage:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:0 reslen:106 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_command 0ms

The differences between the two formats are:

  • OP_QUERY/OP_GET_MORE diagnostic log entries begin with the word query and list the query predicate and other modifiers after "query:". Like all other commands, the find command log line instead begins with the word command and lists the command parameters object after "command:".
  • The find command log lines omit the ntoreturn and ntoskip information, since this is redundant with the find command parameters. The find command has parameters named skip, limit, and batchSize which contain this information.

Similarly, a getMore command will be logged just like any other command, and not like an OP_GET_MORE wire protocol message:

2015-09-23T15:13:27.141-0400 I COMMAND  [conn2] command test.collection command: getMore { getMore: 17696123619, collection: "collection", batchSize: 2.0 } ntoreturn:1 ntoskip:0 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:0 reslen:123 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_command 0ms



 Comments   
Comment by Githook User [ 23/Sep/15 ]

Author:

{u'username': u'dstorch', u'name': u'David Storch', u'email': u'david.storch@10gen.com'}

Message: SERVER-19568 omit ntoreturn and ntoskip fields from find command log line
Branch: master
https://github.com/mongodb/mongo/commit/75115dfaab9da2854b0fd892ce029781afea2731

Comment by J Rassi [ 15/Sep/15 ]

Relatedly, it is somewhat confusing that "ntoreturn: 0" is listed in the diagnostic log entry for find commands that have a non-zero batchSize or limit. For example:

2015-09-15T17:12:02.952-0400 I COMMAND  [conn2] command test.foo command: find { find: "foo", filter: {}, limit: 5.0, singleBatch: false } planSummary: COLLSCAN ntoreturn:0 ntoskip:0 keysExamined:0 docsExamined:5 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:5 reslen:224 locks:{ Global: { acquireCount: { r: 2 } }, MMAPV1Journal: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { R: 1 } } } protocol:op_command 0ms

Generated at Thu Feb 08 03:51:24 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.