OPERATIONAL DEFECT DATABASE
...
...
BugZero found this defect 2714 days ago.
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.
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
see description
