[SERVER-28196] Legacy query and getMore should appear in a consistent format across currentOp, profiler and logs Created: 06/Mar/17  Updated: 06/Dec/17  Resolved: 07/Mar/17

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

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

Issue Links:
Backports
Documented
Backwards Compatibility: Minor Change
Backport Requested:
v3.4
Sprint: Query 2017-03-27
Participants:

 Description   

The following inconsistencies exist in how legacy query/getMore are represented in diagnostic output:

In currentOp:

  • Legacy queries are upconverted to resemble find commands.
  • Legacy getMores are not upconverted. The original query filter, but not the remainder of the query object, is shown in the "query" field rather than the originatingCommand field.

In the profiler:

  • Legacy queries are upconverted to find commands.
  • Legacy getMores are upconverted to getMore commands. The original query is not recorded.

In the logs:

  • No upconversion of either operation is performed.
  • Legacy getMore displays the original query's filter in the "query" field.

Upconversion and display of legacy queries and getMores should be consistent across currentOp/profiler/logs, and in the case of getMores the original operation should be shown in the originatingCommand field.



 Comments   
Comment by David Storch [ 10/Oct/17 ]

Hi steve.renaker, the originatingCommand field associated with a getMore displays the command which caused the cursor to be opened, typically a find or aggregate command. It contains all of the command parameters, such as the pipeline for aggregate or the filter and sort for find. Both find and aggregate also accept a comment parameter. This does not affect the execution of the command, but instead is a place where applications can put a descriptive string that will appear in the logs and in profiler entries. The comment can help operators trace from the logs/profiler back to the behavior of their application. The originatingCommand field in getMore is also particularly useful for tracing a getMore log line or profiler entry back to the application. Hopefully that was helpful, but let me know if I can clarify further.

Comment by Steve Renaker (Inactive) [ 09/Oct/17 ]

david.storch can you tell me a bit more about the originatingCommand.comment field? What is its purpose? Thanks for any help.

Comment by David Storch [ 07/Mar/17 ]

The following summarizes, with examples, the behavior changes made under this ticket in commit 3cba97198638.

Logs

Legacy find operations are now logged in an upconverted format, appearing as find commands. Before this change:

2017-03-07T12:02:46.652-0500 I COMMAND  [conn1] query test.c appName: "MongoDB Shell" query: { a: 1.0 } planSummary: COLLSCAN ntoreturn:3 ntoskip:0 keysExamined:0 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:53 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } 0ms

After:

2017-03-07T12:03:05.261-0500 I COMMAND  [conn1] query test.c appName: "MongoDB Shell" query: { find: "c", filter: { a: 1.0 }, ntoreturn: 3 } planSummary: COLLSCAN ntoreturn:3 ntoskip:0 keysExamined:0 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:53 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } 0ms

Similarly, legacy OP_GET_MORE operations are now upconverted such that their log format resembles that of the getMore command. This also includes inclusion of the full originatingCommand field, which displays the operation which generated the cursor on which the getMore is acting. Before:

2017-03-07T12:04:33.287-0500 I COMMAND  [conn1] getmore test.c appName: "MongoDB Shell" query: { a: 1.0 } planSummary: COLLSCAN cursorid:19659529935 ntoreturn:2 keysExamined:0 docsExamined:0 cursorExhausted:1 numYields:0 nreturned:0 reslen:20 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } 0ms

After:

2017-03-07T12:05:37.112-0500 I COMMAND  [conn1] getmore test.c appName: "MongoDB Shell" query: { getMore: 18717481128, collection: "c", batchSize: 2 } originatingCommand: { find: "c", filter: { a: 1.0 }, ntoreturn: 2 } planSummary: COLLSCAN cursorid:18717481128 ntoreturn:2 keysExamined:0 docsExamined:0 cursorExhausted:1 numYields:0 nreturned:0 reslen:20 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } 0ms

Profiler

Profiler entries for legacy getMore now contain the originatingCommand. The originatingCommand is displayed in an upconverted format if the cursor was generated by a legacy OP_QUERY find.

{ "op" : "getmore", "ns" : "legacy_originatingcommand.test", "query" : { "getMore" : NumberLong("21180100511"), "collection" : "test", "batchSize" : NumberLong(2) }, "originatingCommand" : { "find" : "test", "filter" : {  }, "comment" : "TEST: getMore" }, "cursorid" : 21180100511, "keysExamined" : 0, "docsExamined" : 2, "numYield" : 2, "locks" : { "Global" : { "acquireCount" : { "r" : NumberLong(6) } }, "Database" : { "acquireCount" : { "r" : NumberLong(3) } }, "Collection" : { "acquireCount" : { "r" : NumberLong(3) } } }, "nreturned" : 2, "responseLength" : 86, "millis" : 200, "planSummary" : "COLLSCAN", "execStats" : { "stage" : "COLLSCAN", "nReturned" : 4, "executionTimeMillisEstimate" : 0, "works" : 5, "advanced" : 4, "needTime" : 1, "needYield" : 0, "saveState" : 6, "restoreState" : 6, "isEOF" : 0, "invalidates" : 0, "direction" : "forward", "docsExamined" : 4 }, "ts" : ISODate("2017-02-10T03:46:40.148Z"), "client" : "127.0.0.1", "appName" : "MongoDB Shell", "allUsers" : [ ], "user" : "" }

currentOp

Legacy getMore operations are now upconverted to appear as getMore commands in db.currentOp() output. Furthermore, the originatingCommand is now reported, in an upconverted format if the originating command was in fact a legacy OP_QUERY.

{
	"inprog" : [
		{
			"desc" : "conn2",
			"threadId" : "0x70000ff9b000",
			"connectionId" : 2,
			"client" : "127.0.0.1:55394",
			"appName" : "MongoDB Shell",
			"active" : true,
			"opid" : 17,
			"secs_running" : 0,
			"microsecs_running" : NumberLong(140071),
			"op" : "getmore",
			"ns" : "legacy_originatingcommand.test",
			"query" : {
				"getMore" : NumberLong("19022851190"),
				"collection" : "test",
				"batchSize" : NumberLong(2)
			},
			"originatingCommand" : {
				"find" : "test",
				"filter" : {
				},
				"comment" : "TEST: getMore"
			},
			"planSummary" : "COLLSCAN",
			"numYields" : 0,
			"locks" : {
			},
			"waitingForLock" : false,
			"lockStats" : {
				"Global" : {
					"acquireCount" : {
						"r" : NumberLong(2)
					}
				},
				"Database" : {
					"acquireCount" : {
						"r" : NumberLong(1)
					}
				},
				"Collection" : {
					"acquireCount" : {
						"r" : NumberLong(1)
					}
				}
			}
		}
	],
	"ok" : 1
}

Comment by Githook User [ 07/Mar/17 ]

Author:

{u'username': u'gormanb', u'name': u'Bernard Gorman', u'email': u'bernard.gorman@gmail.com'}

Message: SERVER-28196 Make legacy query and getMore appear in a consistent format across currentOp, profiler and logs

Closes #1139

Signed-off-by: David Storch <david.storch@10gen.com>
Branch: master
https://github.com/mongodb/mongo/commit/3cba97198638df3750e3b455e2ad57af7ee536ae

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