Operational Defect Database

BugZero found this defect 2429 days ago.

MongoDB | 399521

[SERVER-29931] Query plan is different for '$gte' and '$gt'

Last update date:

7/29/2017

Affected products:

MongoDB Server

Affected releases:

3.2.8

Fixed releases:

No fixed releases provided.

Description:

Info

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.

Top User Comments

hailong commented on Thu, 6 Jul 2017 08:22:15 +0000: Thanks for your help thomas.schubert commented on Wed, 5 Jul 2017 14:02:26 +0000: 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 hailong commented on Tue, 4 Jul 2017 11:22:24 +0000: 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 hailong commented on Mon, 3 Jul 2017 02:14:40 +0000: Thanks David, I will add explain output as soon as possible. david.storch commented on Fri, 30 Jun 2017 13:51:02 +0000: 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

Additional Resources / Links

Share:

BugZero Risk Score

Coming soon

Status

Closed

Have you been affected by this bug?

cost-cta-background

Do you know how much operational outages are costing you?

Understand the cost to your business and how BugZero can help you reduce those costs.

Discussion

Login to read and write comments.

Have you ever...

had your data corrupted from a

VMware

bug?

Search:

...