[SERVER-16757] Incorrect query report for $explain Created: 07/Jan/15  Updated: 15/Jan/15  Resolved: 08/Jan/15

Status: Closed
Project: Core Server
Component/s: Logging, Shell
Affects Version/s: 2.8.0-rc4
Fix Version/s: 2.8.0-rc5

Type: Bug Priority: Minor - P4
Reporter: Thomas Rueckstiess Assignee: Eric Milkie
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Backwards Compatibility: Fully Compatible
Operating System: ALL
Participants:

 Description   

Using .explain() results in a log line like this:

2015-01-08T00:00:31.433+1100 I QUERY    [conn4] command test.$cmd command: explain { explain: { find: "foo", filter: { a: 1.0 }, options: {} }, verbosity: "queryPlanner" } keyUpdates:0 numYields:0  reslen:383 0ms

But using $explain or ._addSpecial( "$explain", 1 ) results in this log line:

2015-01-08T00:02:58.169+1100 I QUERY    [conn4] command test.foo command: isMaster { query: { a: 1.0 }, $explain: 1.0 } ntoreturn:0 keyUpdates:0 numYields:0  reslen:801 0ms

I don't know where "isMaster" comes from, but it has nothing to do with the query.

Also, using different ways of running explain shows different shell behavior (no linebreaks vs. pretty printed output).

$explain version

> db.foo.find({$query: {a:1}, $explain: true})
{ "queryPlanner" : { "plannerVersion" : 1, "namespace" : "test.foo", "parsedQuery" : { "a" : { "$eq" : 1 } }, "winningPlan" : { "stage" : "COLLSCAN", "filter" : { "a" : { "$eq" : 1 } }, "direction" : "forward" }, "rejectedPlans" : [ ] }, "executionStats" : { "executionSuccess" : true, "nReturned" : 1, "executionTimeMillis" : 0, "totalKeysExamined" : 0, "totalDocsExamined" : 1, "executionStages" : { "stage" : "COLLSCAN", "filter" : { "a" : { "$eq" : 1 } }, "nReturned" : 1, "executionTimeMillisEstimate" : 0, "works" : 3, "advanced" : 1, "needTime" : 1, "needFetch" : 0, "saveState" : 0, "restoreState" : 0, "isEOF" : 1, "invalidates" : 0, "direction" : "forward", "docsExamined" : 1 }, "allPlansExecution" : [ ] }, "serverInfo" : { "host" : "enter.local", "port" : 27017, "version" : "2.8.0-rc4", "gitVersion" : "3ad571742911f04b307f0071979425511c4f2570" } }

_addSpecial version

> db.foo.find({a:1})._addSpecial( "$explain", 1 )
{ "queryPlanner" : { "plannerVersion" : 1, "namespace" : "test.foo", "parsedQuery" : { "a" : { "$eq" : 1 } }, "winningPlan" : { "stage" : "COLLSCAN", "filter" : { "a" : { "$eq" : 1 } }, "direction" : "forward" }, "rejectedPlans" : [ ] }, "executionStats" : { "executionSuccess" : true, "nReturned" : 1, "executionTimeMillis" : 0, "totalKeysExamined" : 0, "totalDocsExamined" : 1, "executionStages" : { "stage" : "COLLSCAN", "filter" : { "a" : { "$eq" : 1 } }, "nReturned" : 1, "executionTimeMillisEstimate" : 0, "works" : 3, "advanced" : 1, "needTime" : 1, "needFetch" : 0, "saveState" : 0, "restoreState" : 0, "isEOF" : 1, "invalidates" : 0, "direction" : "forward", "docsExamined" : 1 }, "allPlansExecution" : [ ] }, "serverInfo" : { "host" : "enter.local", "port" : 27017, "version" : "2.8.0-rc4", "gitVersion" : "3ad571742911f04b307f0071979425511c4f2570" } }

.explain() version

> db.foo.find({a:1}).explain()
{
	"queryPlanner" : {
		"plannerVersion" : 1,
		"namespace" : "test.foo",
		"parsedQuery" : {
			"a" : {
				"$eq" : 1
			}
		},
		"winningPlan" : {
			"stage" : "COLLSCAN",
			"filter" : {
				"a" : {
					"$eq" : 1
				}
			},
			"direction" : "forward"
		},
		"rejectedPlans" : [ ]
	},
	"serverInfo" : {
		"host" : "enter.local",
		"port" : 27017,
		"version" : "2.8.0-rc4",
		"gitVersion" : "3ad571742911f04b307f0071979425511c4f2570"
	},
	"ok" : 1
}



 Comments   
Comment by Githook User [ 08/Jan/15 ]

Author:

{u'username': u'milkie', u'name': u'Eric Milkie', u'email': u'milkie@10gen.com'}

Message: SERVER-16757 a query with is not a command
Branch: master
https://github.com/mongodb/mongo/commit/a1cfc87572e26bcae1e337a608cc096b685662db

Comment by Thomas Rueckstiess [ 07/Jan/15 ]

To reproduce:

1. start mongod with -v
2. open shell, run

db.foo.find({$query: {a: 1}, $explain: 1})

3. log file contains these messages

2015-01-08T01:17:56.225+1100 I QUERY    [conn3] command test.$cmd command: isMaster { isMaster: 1.0, forShell: 1.0 } keyUpdates:0 numYields:0  reslen:178 0ms
2015-01-08T01:18:40.365+1100 I QUERY    [conn3] command test.foo command: isMaster { $query: { a: 1.0 }, $explain: 1.0 } ntoreturn:0 keyUpdates:0 numYields:0  reslen:659 0ms
2015-01-08T01:18:40.369+1100 I QUERY    [conn3] command test.$cmd command: isMaster { isMaster: 1.0, forShell: 1.0 } keyUpdates:0 numYields:0  reslen:178 0ms

Comment by Eric Milkie [ 07/Jan/15 ]

You're right, and I wonder if this is related to SERVER-16556.

Comment by Thomas Rueckstiess [ 07/Jan/15 ]

Okay, looks like .explain() is identical to the command. And $explain is identical to _addSpecial.

But none of these should contain a reference to the "isMaster" command in the log message. Perhaps something is not initialized correctly and it uses the previous command's name.

Comment by Eric Milkie [ 07/Jan/15 ]

Using the shell helper in 2.8 uses the new "explain" command, if it is supported by the server. The command has different behavior than using the query modifier. If you try running the "explain" command by hand without the shell helper, it may have closer behavior to the shell helper.

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