[SERVER-17182] Planner ignores index filter and uses slow query plan Created: 04/Feb/15  Updated: 16/Feb/18  Resolved: 06/Feb/15

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

Type: Bug Priority: Critical - P2
Reporter: Ben Polidore Assignee: David Storch
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

windows server 2008 R2


Issue Links:
Related
related to SERVER-28116 Consider creating an index filter par... Backlog
Operating System: Windows
Steps To Reproduce:

Use this schema under heavy load.

Participants:

 Description   

Background

I have a collection that receives a high number of writes (hundreds per second), so the plan cache gets reset a lot. I see in my slow query log inefficient index choices that result in a large number of "nscanned".

I assumed that this was because the plan cache gets reset very often and it's possible that a given query results in 0 documents, so a very simple index choice wins, but as the number of returned documents increases, that simple approach would get slower. So basically, every few thousand queries, I might ask for something that is easily handled by a single index, so that one wins and "infects" the next thousand queries with very slow outcome due to query plan caching.

OK, fine, so I decided to employ an index filter.

It seems to be taking it: after using the index filter if I do find().explain() for the query shape, I get filterSet: true, and it runs in "0" ms.

But I still see slow queries in my log with the poor index choice, so it's ignoring my index filter!!! (see below for details)

The query is pretty complex, but explain seems to figure it out.

Is there any reason why mongo would ignore my query planner? Something to do with blocking vs. non-blocking plans? I'm at a loss.

Details

The Index Filter

db.runCommand({planCacheSetFilter: 'orders',
               query: {
                 "date" : "2015.02.04",
                 "symbol" : {
                   "$in" : [
                     "ESRX"
                   ]
                 },
                 "$or" : [
                   {
                     "_id" : "20150204-USA-9259-6"
                   },
                   {
                     "initialGateId" : "20150204-USA-9259-6"
                   },
                   {
                     "openChildOrders.id" : "USA-9259-6"
                   },
                   {
                     "intermediateIds" : "USA-9259-6"
                   }
                 ]
               },
               indexes: [
                 {
                   "_id" : 1
                 },
                 {
                   "initialGateId" : 1
                 },
                 {
                   "openChildOrders.id" : 1
                 },
                 {
                   "intermediateIds" : -1
                 }
               ]
              });

Explain Output

db.orders.find({ date: "2015.02.04", symbol: { $in: [ "TGE" ] }, $or: [ { _id: "20150204-USA-11455-1263" }, { initialGateId: "20150204-USA-11455-1263" }, { "openChildOrders.id": "USA-11455-1263" }, { intermediateIds: "USA-11455-1263" } ] }).explain()
{
        "clauses" : [
                {
                        "cursor" : "BtreeCursor _id_",
                        "isMultiKey" : false,
                        "n" : 1,
                        "nscannedObjects" : 1,
                        "nscanned" : 1,
                        "scanAndOrder" : false,
                        "indexOnly" : false,
                        "nChunkSkips" : 0,
                        "indexBounds" : {
                                "_id" : [
                                        [
                                                "20150204-USA-11455-1263",
                                                "20150204-USA-11455-1263"
                                        ]
                                ]
                        }
                },
                {
                        "cursor" : "BtreeCursor intermediateIds_-1",
                        "isMultiKey" : true,
                        "n" : 1,
                        "nscannedObjects" : 1,
                        "nscanned" : 1,
                        "scanAndOrder" : false,
                        "indexOnly" : false,
                        "nChunkSkips" : 0,
                        "indexBounds" : {
                                "intermediateIds" : [
                                        [
                                                "USA-11455-1263",
                                                "USA-11455-1263"
                                        ]
                                ]
                        }
                },
                {
                        "cursor" : "BtreeCursor openChildOrders.id_1",
                        "isMultiKey" : true,
                        "n" : 0,
                        "nscannedObjects" : 0,
                        "nscanned" : 0,
                        "scanAndOrder" : false,
                        "indexOnly" : false,
                        "nChunkSkips" : 0,
                        "indexBounds" : {
                                "openChildOrders.id" : [
                                        [
                                                "USA-11455-1263",
                                                "USA-11455-1263"
                                        ]
                                ]
                        }
                },
                {
                        "cursor" : "BtreeCursor initialGateId_1",
                        "isMultiKey" : false,
                        "n" : 0,
                        "nscannedObjects" : 0,
                        "nscanned" : 0,
                        "scanAndOrder" : false,
                        "indexOnly" : false,
                        "nChunkSkips" : 0,
                        "indexBounds" : {
                                "initialGateId" : [
                                        [
                                                "20150204-USA-11455-1263",
                                                "20150204-USA-11455-1263"
                                        ]
                                ]
                        }
                }
        ],
        "cursor" : "QueryOptimizerCursor",
        "n" : 1,
        "nscannedObjects" : 2,
        "nscanned" : 2,
        "nscannedObjectsAllPlans" : 2,
        "nscannedAllPlans" : 2,
        "scanAndOrder" : false,
        "nYields" : 0,
        "nChunkSkips" : 0,
        "millis" : 0,
        "server" : "VM-PRISMUAT-NY:27017",
        "filterSet" : true
}
 

The slow query error

Here you'll see that the plan it uses is an IXSCAN of symbol. If I use a hint that forces this query to use symbol (without the index filter), it runs in about 9ms, but that is still very slow for my application. Using the proper indexes, it runs in "0" ms.

2015-02-04T15:04:43.553-0500 [conn39315] query prism-orders.orders query: { date: "2015.02.04", symbol: { $in: [ "TGE" ] }, $or: [ { _id: "20150204-USA-11455-1263" }, { initialGateId: "20150204-USA-11455-1263" }, { openChildOrders.id: "USA-11455-1263" }, { intermediateIds: "USA-11455-1263" } ] } planSummary: IXSCAN { symbol: 1 } ntoreturn:0 ntoskip:0 nscanned:229 nscannedObjects:229 keyUpdates:0 numYields:11 locks(micros) r:742721 nreturned:1 reslen:82 561ms



 Comments   
Comment by David Storch [ 06/Feb/15 ]

Hi polidore,

Glad to hear that you resolved your issue. I am going to close this ticket as Works as Designed.

I agree that there is room for improvement in MongoDB's plan selection and plan caching behavior. One related ticket which may be of interest is SERVER-15225. Please watch this ticket for updates.

Best,
Dave

Comment by Ben Polidore [ 06/Feb/15 ]

We resolved it!!!

The issue is that our index filters didn't have the projection that we were using in our application. It might be nice to be able to wildcard the projection and the sort when creating index filters.

One more wrinkle for anyone else that has this issue: the index filters were still being intermittently ignored until we disconnected and reconnected some very busy clients.

In general, I think mongodb may need some improvement here. The plan cache gets reset VERY often in our db, and it picks the wrong plan very often as well. In an environment like ours (not many docs, very many in place updates), it might be better to have some kind of longer term statistic on the efficiency of various plans instead of doing 1 trial and keeping it for the next 1000 updates.

Thanks,
Ben

Comment by David Storch [ 05/Feb/15 ]

Hi polidore,

It does appear from the log line above that the index filter is not getting applied. Could you please run the following command against each mongod in your cluster and reply with the resulting output?

db.getSiblingDB("prism-orders").runCommand({planCacheListFilters: "orders"});

As a first step I would like to verify that the plan cache filter is correctly configured. Also, please note that plan cache filters are not persistent, and must be re-configured after every restart.

One follow-up question: is the slow query from the logs above being routed through a mongos?

Best,
Dave

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