[SERVER-49469] explain executionStats for $unionWith incorrectly shows COLLSCAN for inner pipeline Created: 13/Jul/20  Updated: 29/Oct/23  Resolved: 12/Aug/20

Status: Closed
Project: Core Server
Component/s: Aggregation Framework
Affects Version/s: 4.4.0-rc13
Fix Version/s: 4.7.0, 4.4.2

Type: Bug Priority: Major - P3
Reporter: Asya Kamsky Assignee: Ted Tuckman
Resolution: Fixed Votes: 0
Labels: qopt-team
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Backports
Related
related to SERVER-50246 $unionWith explain loses information ... Closed
related to SERVER-45535 Support explain for $unionWith aggreg... Closed
Backwards Compatibility: Minor Change
Operating System: ALL
Backport Requested:
v4.4
Sprint: Query 2020-08-10, Query 2020-08-24
Participants:

 Description   

db.testcoll1.createIndex({testField1:1})
db.testcoll2.explain().aggregate( [ { $unionWith : { coll: "testcoll1", pipeline : [ { $match : { testField1 : { $gt : 2 } } } ] } } ] )
// shows correct plan
db.testcoll2.explain("executionStats").aggregate( [ { $unionWith : { coll: "testcoll1", pipeline : [ { $match : { testField1 : { $gt : 2 } } } ] } } ] )
// shows incorrect plan!
{
	"stages" : [
		{
			"$cursor" : {
				"queryPlanner" : {
					"plannerVersion" : 1,
					"namespace" : "test.testcoll2",
					"indexFilterSet" : false,
					"parsedQuery" : {
 
					},
					"winningPlan" : {
						"stage" : "EOF"
					},
					"rejectedPlans" : [ ]
				},
				"executionStats" : {
					"executionSuccess" : true,
					"nReturned" : 0,
					"executionTimeMillis" : 0,
					"totalKeysExamined" : 0,
					"totalDocsExamined" : 0,
					"executionStages" : {
						"stage" : "EOF",
						"nReturned" : 0,
						"executionTimeMillisEstimate" : 0,
						"works" : 1,
						"advanced" : 0,
						"needTime" : 0,
						"needYield" : 0,
						"saveState" : 1,
						"restoreState" : 1,
						"isEOF" : 1
					},
					"allPlansExecution" : [ ]
				}
			},
			"nReturned" : NumberLong(0),
			"executionTimeMillisEstimate" : NumberLong(0)
		},
		{
			"$unionWith" : {
				"coll" : "testcoll1",
				"pipeline" : [
					{
						"$cursor" : {
							"queryPlanner" : {
								"plannerVersion" : 1,
								"namespace" : "test.testcoll1",
								"indexFilterSet" : false,
								"parsedQuery" : {
 
								},
								"queryHash" : "8B3D4AB8",
								"planCacheKey" : "8B3D4AB8",
								"winningPlan" : {
									"stage" : "COLLSCAN",
									"direction" : "forward"
								},
								"rejectedPlans" : [ ]
							},
							"executionStats" : {
								"executionSuccess" : true,
								"nReturned" : 0,
								"executionTimeMillis" : 0,
								"totalKeysExamined" : 0,
								"totalDocsExamined" : 0,
								"executionStages" : {
									"stage" : "COLLSCAN",
									"nReturned" : 0,
									"executionTimeMillisEstimate" : 0,
									"works" : 0,
									"advanced" : 0,
									"needTime" : 0,
									"needYield" : 0,
									"saveState" : 1,
									"restoreState" : 0,
									"isEOF" : 0,
									"direction" : "forward",
									"docsExamined" : 0
								},
								"allPlansExecution" : [ ]
							}
						},
						"nReturned" : NumberLong(0),
						"executionTimeMillisEstimate" : NumberLong(0)
					}
				]
			},
			"nReturned" : NumberLong(0),
			"executionTimeMillisEstimate" : NumberLong(1)
		}
	],
	"serverInfo" : {
		"host" : "asyas-mbp-4.lan",
		"port" : 27017,
		"version" : "4.4.0-rc7",
		"gitVersion" : "b79b53f55a5c148fd297b81a45c08d08e2cf8f94"
	},
	"ok" : 1
}

Note that index stats on testcoll1 show the index access get incremented so I believe that the error is somewhere in massaging output for executionStats for $unionWith stage. Note that the filter is missing (no parsedQuery).



 Comments   
Comment by Githook User [ 11/Sep/20 ]

Author:

{'name': 'Ted Tuckman', 'email': 'ted.tuckman@mongodb.com', 'username': 'TedTuckman'}

Message: SERVER-49469 Fix union inner pipeline explain

(cherry picked from commit 274192ab7d429710e0f69f0b1d922005fca9d516)
Branch: v4.4
https://github.com/mongodb/mongo/commit/a0420a228b92b8ff8fac79e053e6576364292c39

Comment by Ted Tuckman [ 20/Aug/20 ]

I had the wrong ticket number in the message.

Author:

{'name': 'Ted Tuckman', 'email': 'ted.tuckman@mongodb.com', 'username': 'TedTuckman'}

Message: SERVER-49649 Fix union inner pipeline explain
Branch: master
https://github.com/mongodb/mongo/commit/274192ab7d429710e0f69f0b1d922005fca9d516

Comment by Ted Tuckman [ 12/Aug/20 ]

This changed the unionWith explain output, anything depending on that may have to be changed.

Comment by Asya Kamsky [ 13/Jul/20 ]

A few tests show that it's only the $cursor stage inside $unionWith that doesn't return correct results, if there are subsequent stages in the $unionWith pipeline they seem to show correct number of documents passing through/returned.

Comment by Asya Kamsky [ 13/Jul/20 ]

Note that if you insert a document into testcoll1 that matches you get executionStats that ends like this (abbreviated/removed some fields):

...
	"nReturned" : NumberLong(0),
},
{
	"$unionWith" : {
		"coll" : "testcoll1",
		"pipeline" : [
			{
				"$cursor" : {
					"queryPlanner" : {
						"parsedQuery" : {
						},
						"winningPlan" : {
						"stage" : "COLLSCAN",
						}
					},
					"executionStats" : {
						"executionSuccess" : true,
						"nReturned" : 0,
						"executionTimeMillis" : 0,
						"totalKeysExamined" : 0,
						"totalDocsExamined" : 0,
						"executionStages" : {
                                                   ...
						}
					}
				},
				"nReturned" : NumberLong(0),
			}
		]
	},
	"nReturned" : NumberLong(1),
}
],
 

Comment by Asya Kamsky [ 13/Jul/20 ]

Note that results from the pipeline are correct, and results from bare explain are correct.  The only incorrect output is from executionStats (and even then it looks like the index is found and used during planning but somehow the wrong thing gets printed out)

Generated at Thu Feb 08 05:19:56 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.