[SERVER-13124] Query with SORT_MERGE stage returns same document twice Created: 10/Mar/14  Updated: 10/Dec/14  Resolved: 11/Mar/14

Status: Closed
Project: Core Server
Component/s: Querying
Affects Version/s: 2.6.0-rc1
Fix Version/s: None

Type: Improvement Priority: Major - P3
Reporter: J Rassi Assignee: Unassigned
Resolution: Done Votes: 0
Labels: 26qa
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Participants:

 Description   

The example below shows a query that returns "n" larger than the size of the collection.

Set up:

> for(i=0;i<10000;i++){db.foo.insert({a:1,b:1,c:1})}

Issue a long-running series of updates:

> for(i=0;;i++){eval("db.foo.update({},{$set:{f"+i+":true}},false,true)");}

Meanwhile, run the following query (and note that itcount() will return values greater than 10000, the number of documents in the collection):

> db.foo.find({$or:[{a:1}, {b:1}]}).sort({c:1}).itcount()
7979
> db.foo.find({$or:[{a:1}, {b:1}]}).sort({c:1}).itcount()
10000
> db.foo.find({$or:[{a:1}, {b:1}]}).sort({c:1}).itcount()
11038

Full explain:

> db.foo.find({$or:[{a:1}, {b:1}]}).sort({c:1}).explain(true)
{
	"clauses" : [
		{
			"cursor" : "BtreeCursor a_1_c_1",
			"isMultiKey" : false,
			"n" : 11126,
			"nscannedObjects" : 0,
			"nscanned" : 11126,
			"scanAndOrder" : false,
			"indexOnly" : false,
			"nChunkSkips" : 0,
			"indexBounds" : {
				"a" : [
					[
						1,
						1
					]
				],
				"c" : [
					[
						{
							"$minElement" : 1
						},
						{
							"$maxElement" : 1
						}
					]
				]
			}
		},
		{
			"cursor" : "BtreeCursor b_1_c_1",
			"isMultiKey" : false,
			"n" : 11126,
			"nscannedObjects" : 0,
			"nscanned" : 11126,
			"scanAndOrder" : false,
			"indexOnly" : false,
			"nChunkSkips" : 0,
			"indexBounds" : {
				"b" : [
					[
						1,
						1
					]
				],
				"c" : [
					[
						{
							"$minElement" : 1
						},
						{
							"$maxElement" : 1
						}
					]
				]
			}
		}
	],
	"cursor" : "QueryOptimizerCursor",
	"n" : 11126,
	"nscannedObjects" : 0,
	"nscanned" : 22252,
	"nscannedObjectsAllPlans" : 0,
	"nscannedAllPlans" : 22252,
	"scanAndOrder" : false,
	"nYields" : 267,
	"nChunkSkips" : 0,
	"millis" : 2559,
	"allPlans" : [
		{
			"clauses" : [
				{
					"cursor" : "BtreeCursor a_1_c_1",
					"isMultiKey" : false,
					"n" : 11126,
					"nscannedObjects" : 0,
					"nscanned" : 11126,
					"scanAndOrder" : false,
					"indexOnly" : false,
					"nChunkSkips" : 0,
					"indexBounds" : {
						"a" : [
							[
								1,
								1
							]
						],
						"c" : [
							[
								{
									"$minElement" : 1
								},
								{
									"$maxElement" : 1
								}
							]
						]
					}
				},
				{
					"cursor" : "BtreeCursor b_1_c_1",
					"isMultiKey" : false,
					"n" : 11126,
					"nscannedObjects" : 0,
					"nscanned" : 11126,
					"scanAndOrder" : false,
					"indexOnly" : false,
					"nChunkSkips" : 0,
					"indexBounds" : {
						"b" : [
							[
								1,
								1
							]
						],
						"c" : [
							[
								{
									"$minElement" : 1
								},
								{
									"$maxElement" : 1
								}
							]
						]
					}
				}
			],
			"cursor" : "QueryOptimizerCursor",
			"n" : 11126,
			"nscannedObjects" : 0,
			"nscanned" : 22252,
			"scanAndOrder" : false,
			"nChunkSkips" : 0
		}
	],
	"server" : "Rassi-MacBook-Pro.local:27017",
	"filterSet" : false,
	"stats" : {
		"type" : "FETCH",
		"works" : 33394,
		"yields" : 267,
		"unyields" : 267,
		"invalidates" : 3365,
		"advanced" : 11126,
		"needTime" : 22254,
		"needFetch" : 13,
		"isEOF" : 1,
		"alreadyHasObj" : 0,
		"forcedFetches" : 0,
		"matchTested" : 0,
		"children" : [
			{
				"type" : "SORT_MERGE",
				"works" : 33380,
				"yields" : 267,
				"unyields" : 267,
				"invalidates" : 3365,
				"advanced" : 11126,
				"needTime" : 22254,
				"needFetch" : 0,
				"isEOF" : 1,
				"dupsTested" : 22252,
				"dupsDropped" : 11126,
				"forcedFetches" : 0,
				"children" : [
					{
						"type" : "IXSCAN",
						"works" : 11127,
						"yields" : 267,
						"unyields" : 267,
						"invalidates" : 3365,
						"advanced" : 11126,
						"needTime" : 0,
						"needFetch" : 0,
						"isEOF" : 1,
						"keyPattern" : "{ a: 1.0, c: 1.0 }",
						"boundsVerbose" : "field #0['a']: [1.0, 1.0], field #1['c']: [MinKey, MaxKey]",
						"isMultiKey" : 0,
						"yieldMovedCursor" : 0,
						"dupsTested" : 0,
						"dupsDropped" : 0,
						"seenInvalidated" : 0,
						"matchTested" : 0,
						"keysExamined" : 11126,
						"children" : [ ]
					},
					{
						"type" : "IXSCAN",
						"works" : 11127,
						"yields" : 267,
						"unyields" : 267,
						"invalidates" : 3365,
						"advanced" : 11126,
						"needTime" : 0,
						"needFetch" : 0,
						"isEOF" : 1,
						"keyPattern" : "{ b: 1.0, c: 1.0 }",
						"boundsVerbose" : "field #0['b']: [1.0, 1.0], field #1['c']: [MinKey, MaxKey]",
						"isMultiKey" : 0,
						"yieldMovedCursor" : 0,
						"dupsTested" : 0,
						"dupsDropped" : 0,
						"seenInvalidated" : 0,
						"matchTested" : 0,
						"keysExamined" : 11126,
						"children" : [ ]
					}
				]
			}
		]
	}
}



 Comments   
Comment by J Rassi [ 11/Mar/14 ]

Resolving: works as designed. This behavior is a known consequence of our isolation semantics.

Quoting from plan_stage.h: "Any data inserted, deleted, or modified during a yield that should be returned by a query may or may not be returned by that query. The query could return: nothing; the data before; the data after; or both the data before and the data after."

In this case, the query is returning "the data before and the data after." The index scan returns the document, then the document is moved (and, with the diskloc change, the index entry is moved ahead of the index cursor), then the index scan encounters the same document again later in the btree and returns it a second time.

Comment by J Rassi [ 10/Mar/14 ]

I filed this ticket originally against explain().n, but now I realize I can also reproduce this with itcount(), and that the index scan stages are also reporting "advanced" larger than the collection size. Updated title/description accordingly.

Comment by J Rassi [ 10/Mar/14 ]

Likely culprit? https://github.com/mongodb/mongo/blob/25596dbf48b18a76d3d2cdfdf1fcf23a43e46316/src/mongo/db/exec/merge_sort.cpp#L171

"advanced" is incremented even when the stage returns NEED_TIME.

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