[SERVER-29931] Query plan is different for '$gte' and '$gt' Created: 30/Jun/17  Updated: 29/Jul/17  Resolved: 05/Jul/17

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

Type: Bug Priority: Critical - P2
Reporter: hailong cao Assignee: Kelsey Schubert
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
duplicates SERVER-22133 COUNT_SCAN plans are not generated pr... Closed
Operating System: ALL
Steps To Reproduce:

see description

Participants:

 Description   

version 3.2.8 (wildTiger):

[dbshell]: db.collection.find({crt: {$lte: new Date(1467047134260), $gt: new Date(1466442334260) }}).maxTimeMS(15000).count()
[mongd log]: 
2017-06-30T07:15:24.477+0000 I COMMAND  [conn5609213] query: { crt: { $lte: new Date(1467047134260), $gt: new Date(1466442334260) } }, maxTimeMS: 15000.0, fields: {} } planSummary: *IXSCAN* { crt: 1, wh: 1 } keyUpdates:0 writeConflicts:0 exception: operation exceeded time limit code:50 numYields:7019 reslen:74 locks:{ Global: { acquireCount: { r: 14040 } }, Database: { acquireCount: { r: 7020 } }, Collection: { acquireCount: { r: 7020 } } } protocol:op_command *15201ms*

if change the '$gt' to '$gte', it then shows different:

[dbshell]:  db.collection.find({crt: {$lte: new Date(1467047134260), $gte: new Date(1466442334260) }}).maxTimeMS(15000).count()
[mongd log]: 2017-06-30T07:14:41.683+0000 I COMMAND  [conn5609213] count { count: "order", query: { crt: { $lte: new Date(1467047134260), $gte: new Date(1466442334260) } }, maxTimeMS: 15000.0, fields: {} } planSummary: *COUNT_SCAN* { crt: 1, wh: 1 } keyUpdates:0 writeConflicts:0 numYields:20357 reslen:47 locks:{ Global: { acquireCount: { r: 40716 } }, Database: { acquireCount: { r: 20358 } }, Collection: { acquireCount: { r: 20358 } } } protocol:op_command *1962ms*

I tested with all the combination of '$lt'/''$lte', 'gt'/'gte', only when '$lte' and '$gte' using together can make mongo use COUNT_SCAN queryplan, which is much much faster.



 Comments   
Comment by hailong cao [ 06/Jul/17 ]

Thanks for your help

Comment by Kelsey Schubert [ 05/Jul/17 ]

Hi hailong,

Thanks for the additional information. It appears this behavior is the result of SERVER-22133, which has been fixed in MongoDB 3.4. Dave explains the issue in this comment, and you can confirm that this is the same issue by executing similar commands as described in my comment to check and clear the contents of the plan cache to temporarily resolve the issue.

If this issue is critical for your deployment, I would recommend upgrading to MongoDB 3.4 to take advantage of the fix described in the SERVER-22133.

Kind regards,
Thomas

Comment by hailong cao [ 04/Jul/17 ]

Interestingly, run with:
db.collection.explain("allPlansExecution").find({crt: {$lte: new Date(1467047134260), $gt: new Date(1466442334260) }}).maxTimeMS(15000).count()
It shows the correct query plan (as expected) won: COUNT

{
	"queryPlanner" : {
		"plannerVersion" : 1,
		"namespace" : "******",
		"indexFilterSet" : false,
		"parsedQuery" : {
			"$and" : [
				{
					"crt" : {
						"$lte" : ISODate("2016-06-27T17:05:34.260Z")
					}
				},
				{
					"crt" : {
						"$gt" : ISODate("2016-06-20T17:05:34.260Z")
					}
				}
			]
		},
		"winningPlan" : {
			"stage" : "COUNT",
			"inputStage" : {
				"stage" : "COUNT_SCAN",
				"keyPattern" : {
					"crt" : 1,
					"wh" : 1
				},
				"indexName" : "crt_1_wh_1",
				"isMultiKey" : false,
				"isUnique" : false,
				"isSparse" : false,
				"isPartial" : false,
				"indexVersion" : 1
			}
		},
		"rejectedPlans" : [ ]
	},
	"executionStats" : {
		"executionSuccess" : true,
		"nReturned" : 0,
		"executionTimeMillis" : 713,
		"totalKeysExamined" : 2605743,
		"totalDocsExamined" : 0,
		"executionStages" : {
			"stage" : "COUNT",
			"nReturned" : 0,
			"executionTimeMillisEstimate" : 570,
			"works" : 2605743,
			"advanced" : 0,
			"needTime" : 2605742,
			"needYield" : 0,
			"saveState" : 20357,
			"restoreState" : 20357,
			"isEOF" : 1,
			"invalidates" : 0,
			"nCounted" : 2605742,
			"nSkipped" : 0,
			"inputStage" : {
				"stage" : "COUNT_SCAN",
				"nReturned" : 2605742,
				"executionTimeMillisEstimate" : 520,
				"works" : 2605743,
				"advanced" : 2605742,
				"needTime" : 0,
				"needYield" : 0,
				"saveState" : 20357,
				"restoreState" : 20357,
				"isEOF" : 1,
				"invalidates" : 0,
				"keysExamined" : 2605743,
				"keyPattern" : {
					"crt" : 1,
					"wh" : 1
				},
				"indexName" : "crt_1_wh_1",
				"isMultiKey" : false,
				"isUnique" : false,
				"isSparse" : false,
				"isPartial" : false,
				"indexVersion" : 1
			}
		},
		"allPlansExecution" : [ ]
	},
	"serverInfo" : {
		"host" : "******",
		"port" : 27017,
		"version" : "3.2.8",
		"gitVersion" : "ed70e33130c977bda0024c125b56d159573dbaf0"
	},
	"ok" : 1
}

However, if run again without explain(), mogod log shows the query plan goes to IXSCAN again:

2017-07-04T11:18:33.422+0000 I COMMAND  [conn5663523] command  command: count { count: "collection", query: { crt: { $lte: new Date(1467047134260), $gt: new Date(1466442334260) } }, maxTimeMS: 15000.0, fields: {} } planSummary: *IXSCAN* { crt: 1, wh: 1 } keyUpdates:0 writeConflicts:0 *exception: operation exceeded time limit* code:50 numYields:7054 reslen:74 locks:{ Global: { acquireCount: { r: 14110 } }, Database: { acquireCount: { r: 7055 } }, Collection: { acquireCount: { r: 7055 } } } protocol:op_command 15179ms

Comment by hailong cao [ 03/Jul/17 ]

Thanks David, I will add explain output as soon as possible.

Comment by David Storch [ 30/Jun/17 ]

Hi hailong,

Thanks for filing this report. In order to help us investigate, could you please post the "allPlansExecution" explain output for the queries that you tested?

Best,
Dave

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