[SERVER-13675] Plans with differing performance can tie during plan ranking Created: 22/Apr/14  Updated: 11/Jul/16  Resolved: 22/May/14

Status: Closed
Project: Core Server
Component/s: Querying
Affects Version/s: 2.6.1, 2.7.0
Fix Version/s: 2.6.2, 2.7.1

Type: Bug Priority: Critical - P2
Reporter: rgpublic Assignee: David Storch
Resolution: Done Votes: 1
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File QLOG.server13675    
Issue Links:
Depends
Duplicate
is duplicated by SERVER-13866 Wrong index is being picked Closed
Related
related to SERVER-14311 skipping of index keys is not account... Closed
related to SERVER-14423 Plans which fetch different numbers o... Closed
is related to SERVER-15237 Performance issue: Query Plan Cache i... Closed
is related to SERVER-15226 Query plan cache should cache query p... Closed
Operating System: ALL
Backport Completed:
Participants:

 Description   
Issue Status as of May 28, 2014

ISSUE SUMMARY
The query plan ranker chooses plans by "racing" them against each other and choosing the one that produces the most results in the least amount of work. When two or more query plans appear to be equally efficient, the query plan ranker chooses one plan arbitrarily and caches it for later use. This cached plan may be inefficient for subsequent queries using the same query shape but different values.

For example, in a mailbox application with indexes on {sender: 1} and {status: 1}, and a query on {status: "unread", sender: "alice@example.com"} the plan for each of the two indices can return zero documents (assuming no unread emails and no emails from Alice), and therefore tie during plan ranking. If the plan ranker chooses to cache index {status: 1} for this query shape, a subsequent query for {status: "read", sender: "bob@example.com"} would scan through all read emails, a potentially very large number. The index on {sender: 1} is much more selective and would have only looked at emails from Bob, a much smaller subset of documents, making the query more efficient.

USER IMPACT
For collections with multiple indexes, depending on data distribution and choice of indexes, this bug may cause the wrong index to be cached and subsequently cause a scan of a large number of documents. For large data sets, this bug can have a serious impact on performance.

There is a related issue, SERVER-14311, where an inferior plan may be picked for queries with potential impact on query performance.

WORKAROUNDS
Affected users are encouraged to use hint() to help the plan ranker choose the correct indexes. Alternatively, Index Filters can be set up to limit the choice of indexes for a given query shape.

AFFECTED VERSIONS
MongoDB production releases 2.6.0 and 2.6.1 are affected by this issue.

FIX VERSION
The fix is included in the 2.6.2 production release.

RESOLUTION DETAILS
Query plans are no longer cached if they tie in the query plan ranker.

Original Description

This is my query:

{
"type":"folder",
"folder":/^((^|\/)[^\/\.][^\/]*)$/
}

As you can see the old mongo version took 4 seconds. The new version takes about 30 seconds. Sometimes on high server load it even takes a few minutes.

2.4.x gave this explain:

{
   "cursor": "BtreeCursor type_folder multi",
   "isMultiKey": false,
   "n": NumberInt(20),
   "nscannedObjects": NumberInt(20),
   "nscanned": NumberInt(2005419),
   "nscannedObjectsAllPlans": NumberInt(20),
   "nscannedAllPlans": NumberInt(2005419),
   "scanAndOrder": false,
   "indexOnly": false,
   "nYields": NumberInt(151),
   "nChunkSkips": NumberInt(0),
   "millis": NumberInt(4430),
   "indexBounds": {
     "type": [
       [
         "folder",
         "folder" 
      ] 
    ],
     "folder": [
       [
         "",
         [
           
        ] 
      ],
       [
         "/^((^|\\/)[^\\/\\.][^\\/]*)$/",
         "/^((^|\\/)[^\\/\\.][^\\/]*)$/" 
      ] 
    ] 
  },
   "allPlans": [
     {
       "cursor": "BtreeCursor type_folder multi",
       "n": NumberInt(20),
       "nscannedObjects": NumberInt(20),
       "nscanned": NumberInt(2005419),
       "indexBounds": {
         "type": [
           [
             "folder",
             "folder" 
          ] 
        ],
         "folder": [
           [
             "",
             [
               
            ] 
          ],
           [
             "/^((^|\\/)[^\\/\\.][^\\/]*)$/",
             "/^((^|\\/)[^\\/\\.][^\\/]*)$/" 
          ] 
        ] 
      } 
    } 
  ],
   "server": "kelvin:27017" 
}

2.6.0 gives this:

{
   "cursor": "BtreeCursor type",
   "isMultiKey": false,
   "n": NumberInt(20),
   "nscannedObjects": NumberInt(2005419),
   "nscanned": NumberInt(2005419),
   "nscannedObjectsAllPlans": NumberInt(2005579),
   "nscannedAllPlans": NumberInt(14056061),
   "scanAndOrder": false,
   "indexOnly": false,
   "nYields": NumberInt(109671),
   "nChunkSkips": NumberInt(0),
   "millis": NumberInt(30821),
   "indexBounds": {
     "type": [
       [
         "folder",
         "folder" 
      ] 
    ] 
  },
   "allPlans": [
     {
       "cursor": "BtreeCursor type",
       "isMultiKey": false,
       "n": NumberInt(20),
       "nscannedObjects": NumberInt(2005419),
       "nscanned": NumberInt(2005419),
       "scanAndOrder": false,
       "indexOnly": false,
       "nChunkSkips": NumberInt(0),
       "indexBounds": {
         "type": [
           [
             "folder",
             "folder" 
          ] 
        ] 
      } 
    },
     {
       "cursor": "BtreeCursor type_folder",
       "isMultiKey": false,
       "n": NumberInt(20),
       "nscannedObjects": NumberInt(20),
       "nscanned": NumberInt(2005419),
       "scanAndOrder": false,
       "indexOnly": false,
       "nChunkSkips": NumberInt(0),
       "indexBounds": {
         "type": [
           [
             "folder",
             "folder" 
          ] 
        ],
         "folder": [
           [
             "",
             [
               
            ] 
          ],
           [
             "/^((^|\\/)[^\\/\\.][^\\/]*)$/",
             "/^((^|\\/)[^\\/\\.][^\\/]*)$/" 
          ] 
        ] 
      } 
    },
     {
       "cursor": "BtreeCursor type_1_folder_1_geometry_2dsphere",
       "isMultiKey": false,
       "n": NumberInt(20),
       "nscannedObjects": NumberInt(20),
       "nscanned": NumberInt(2005419),
       "scanAndOrder": false,
       "indexOnly": false,
       "nChunkSkips": NumberInt(0),
       "indexBounds": {
         "type": [
           [
             "folder",
             "folder" 
          ] 
        ],
         "folder": [
           [
             "",
             [
               
            ] 
          ],
           [
             "/^((^|\\/)[^\\/\\.][^\\/]*)$/",
             "/^((^|\\/)[^\\/\\.][^\\/]*)$/" 
          ] 
        ],
         "geometry": [
           [
             {
               "$minElement": NumberInt(1) 
            },
             {
               "$maxElement": NumberInt(1) 
            } 
          ] 
        ] 
      } 
    },
     {
       "cursor": "BtreeCursor folder_type_active",
       "isMultiKey": false,
       "n": NumberInt(20),
       "nscannedObjects": NumberInt(20),
       "nscanned": NumberInt(2023543),
       "scanAndOrder": false,
       "indexOnly": false,
       "nChunkSkips": NumberInt(0),
       "indexBounds": {
         "folder": [
           [
             "",
             [
               
            ] 
          ],
           [
             "/^((^|\\/)[^\\/\\.][^\\/]*)$/",
             "/^((^|\\/)[^\\/\\.][^\\/]*)$/" 
          ] 
        ],
         "type": [
           [
             "folder",
             "folder" 
          ] 
        ],
         "active": [
           [
             {
               "$minElement": NumberInt(1) 
            },
             {
               "$maxElement": NumberInt(1) 
            } 
          ] 
        ] 
      } 
    },
     {
       "cursor": "BtreeCursor type_folder_timestamp_desc",
       "isMultiKey": false,
       "n": NumberInt(20),
       "nscannedObjects": NumberInt(20),
       "nscanned": NumberInt(2005419),
       "scanAndOrder": false,
       "indexOnly": false,
       "nChunkSkips": NumberInt(0),
       "indexBounds": {
         "type": [
           [
             "folder",
             "folder" 
          ] 
        ],
         "folder": [
           [
             "",
             [
               
            ] 
          ],
           [
             "/^((^|\\/)[^\\/\\.][^\\/]*)$/",
             "/^((^|\\/)[^\\/\\.][^\\/]*)$/" 
          ] 
        ],
         "timestamp": [
           [
             {
               "$maxElement": NumberInt(1) 
            },
             {
               "$minElement": NumberInt(1) 
            } 
          ] 
        ] 
      } 
    },
     {
       "cursor": "BtreeCursor folder_filename_desc",
       "isMultiKey": false,
       "n": NumberInt(18),
       "nscannedObjects": NumberInt(78),
       "nscanned": NumberInt(2005421),
       "scanAndOrder": false,
       "indexOnly": false,
       "nChunkSkips": NumberInt(0),
       "indexBounds": {
         "folder": [
           [
             "/^((^|\\/)[^\\/\\.][^\\/]*)$/",
             "/^((^|\\/)[^\\/\\.][^\\/]*)$/" 
          ],
           [
             [
               
            ],
             "" 
          ] 
        ],
         "filename": [
           [
             {
               "$maxElement": NumberInt(1) 
            },
             {
               "$minElement": NumberInt(1) 
            } 
          ] 
        ] 
      } 
    },
     {
       "cursor": "BtreeCursor folder",
       "isMultiKey": false,
       "n": NumberInt(2),
       "nscannedObjects": NumberInt(2),
       "nscanned": NumberInt(2005421),
       "scanAndOrder": false,
       "indexOnly": false,
       "nChunkSkips": NumberInt(0),
       "indexBounds": {
         "folder": [
           [
             "",
             [
               
            ] 
          ],
           [
             "/^((^|\\/)[^\\/\\.][^\\/]*)$/",
             "/^((^|\\/)[^\\/\\.][^\\/]*)$/" 
          ] 
        ] 
      } 
    } 
  ],
   "server": "kelvin:27017",
   "filterSet": false,
   "stats": {
     "type": "KEEP_MUTATIONS",
     "works": NumberInt(2005421),
     "yields": NumberInt(109671),
     "unyields": NumberInt(109671),
     "invalidates": NumberInt(411),
     "advanced": NumberInt(20),
     "needTime": NumberInt(2005399),
     "needFetch": NumberInt(0),
     "isEOF": NumberInt(1),
     "children": [
       {
         "type": "FETCH",
         "works": NumberInt(2005420),
         "yields": NumberInt(109671),
         "unyields": NumberInt(109671),
         "invalidates": NumberInt(411),
         "advanced": NumberInt(20),
         "needTime": NumberInt(2005399),
         "needFetch": NumberInt(0),
         "isEOF": NumberInt(1),
         "alreadyHasObj": NumberInt(0),
         "forcedFetches": NumberInt(0),
         "matchTested": NumberInt(20),
         "children": [
           {
             "type": "IXSCAN",
             "works": NumberInt(2005419),
             "yields": NumberInt(109671),
             "unyields": NumberInt(109671),
             "invalidates": NumberInt(411),
             "advanced": NumberInt(2005419),
             "needTime": NumberInt(0),
             "needFetch": NumberInt(0),
             "isEOF": NumberInt(1),
             "keyPattern": "{ type: 1 }",
             "boundsVerbose": "field #0['type']: [\"folder\", \"folder\"]",
             "isMultiKey": NumberInt(0),
             "yieldMovedCursor": NumberInt(0),
             "dupsTested": NumberInt(0),
             "dupsDropped": NumberInt(0),
             "seenInvalidated": NumberInt(0),
             "matchTested": NumberInt(0),
             "keysExamined": NumberInt(2005419),
             "children": [
               
            ] 
          } 
        ] 
      } 
    ] 
  } 
}



 Comments   
Comment by Ramon Fernandez Marina [ 27/Jun/14 ]

Please check SERVER-14311, which may be the issue you're running into. SERVER-13675 is about caching plan rankings, which unfortunately doesn't prevent inferior plans from being used in all cases.

Comment by Sergey Mashinksy [X] [ 24/Jun/14 ]

I can confirm. Successfully reproduced this bug on 2.6.2.

Comment by Wei Kong [ 19/Jun/14 ]

Unfortunately, I don't think this bug is fixed. I tested the same query on mongodb 2.6.2 using the same data set and query and it was still picking the wrong index.

Comment by Githook User [ 25/May/14 ]

Author:

{u'username': u'monkey101', u'name': u'Dan Pasette', u'email': u'dan@10gen.com'}

Message: SERVER-13675 do not cache plans if there is a tie

(backport of 7dcbdc440a56fef19a561f513d8eddd1c2a2b27f)
Branch: v2.6
https://github.com/mongodb/mongo/commit/213700b3af4d53ce7e808dce2c638d98fc4f91db

Comment by Daniel Pasette (Inactive) [ 24/May/14 ]

rassi@10gen.com makes a good point. Is it possible to easily identify when the query predicate matches the prefix of > 1 candidate index?

Comment by J Rassi [ 23/May/14 ]

FWIW, I've been thinking more about query plans that are guaranteed to always tie (and as such will never be cached).

Here's a simple one: given indexes {a: 1, b: 1} and {a: 1, c: 1}, query shape {a: 1} will generate two plans that will always tie. It's probably worthwhile to keep an eye out for other common use cases that will hit this in case we ever reconsider the "don't cache ties" approach for 2.6.

Comment by Githook User [ 22/May/14 ]

Author:

{u'username': u'dstorch', u'name': u'David Storch', u'email': u'david.storch@10gen.com'}

Message: SERVER-13675 do not cache plans if there is a tie
Branch: master
https://github.com/mongodb/mongo/commit/7dcbdc440a56fef19a561f513d8eddd1c2a2b27f

Comment by Wei Kong [ 19/May/14 ]

Please checkout CS12398 which was concluded a duplicate of this ticket . In our case a less efficient index can take much longer to find a record by scanning thousands or tens of thousands records or more. It is not a complete table scan but bad enough to make the db unusable under load . The only solution for us was to downgrade after trying patching the code but it was hard to patch all different query cases . But the doc on downgrade had a bug related to auth which further prevented us from recovering from the outage quickly .

Comment by Asya Kamsky [ 19/May/14 ]

Wei, this bug is about picking a less efficient index over another index. If you're seeing a collection scan instead of an index being used, you might be seeing a different issue which should be filed and triaged separately.

Comment by Wei Kong [ 17/May/14 ]

P3 doesn't justify the severity of this bug.

This bug results in table scan in a database with multiple indexes. It easily overloads the db when there is large collection and decent amount of queries but the right index was not selected . The only fix was to rewrite the code to use hint or downgrade. Either solution is time consuming.

10gen should have advised against anyone from upgrading to 2.6.x until this ticket is fixed. It is very disappointing that 10gen underplayed the severity of this issue and failed customers and caused prolonged outage.

Comment by Asya Kamsky [ 23/Apr/14 ]

One thing that you might consider is {type:1,folder:1} index can and will be used for queries on type only (prefix of an index can be used for queries involving those fields) so you don't need type:1 index at all once you created type:1,folder:1 index.

You also don't need the index on folder only as you have folder, filename. And if we're being technical, even type, folder isn't needed as type, folder are prefixes of two other indexes that can be used for queries on them (as you can see in explain).

Comment by rgpublic [ 23/Apr/14 ]

I've attached the log for 2.6.0 below in case it still helps. I don't know about any of MongoDB's inner workings, but as a novice to all of this, the thing that puzzles me the most here is: My query is about the two keys "type" and "folder" (no sort). And then there is a compound index with exactly that "type" and "folder". I've created it for this very purpose. What greater index in the whole universe could MongoDB possibly find than this ready-made index consisting of exactly these two keys? So I don't understand why MongoDB is even looking for other indexes - but that's just my 2 cents. Probably I overlook something...

===
2014-04-23T16:36:35.523+0200 [conn1] [QLOG] Running query:
2014-04-23T16:36:35.523+0200 [conn1] Running query: query:

{ type: "folder", folder: /^((^|\/)[^\/\.][^\/]*)$/ }

sort: {} projection: {}
2014-04-23T16:36:35.523+0200 [conn1] [QLOG] Tagging the match expression according to cache data:
2014-04-23T16:36:35.523+0200 [conn1] [QLOG] Index 0:

{ _id: 1 }

2014-04-23T16:36:35.523+0200 [conn1] [QLOG] Index 1:

{ filename: 1 }

2014-04-23T16:36:35.523+0200 [conn1] [QLOG] Index 2:

{ folder: 1 }

2014-04-23T16:36:35.523+0200 [conn1] [QLOG] Index 3:

{ type: 1 }

2014-04-23T16:36:35.523+0200 [conn1] [QLOG] Index 4:

{ binary_id: 1 }

2014-04-23T16:36:35.523+0200 [conn1] [QLOG] Index 5:

{ sessionid: 1 }

2014-04-23T16:36:35.523+0200 [conn1] [QLOG] Index 6:

{ type: 1, folder: 1 }

2014-04-23T16:36:35.523+0200 [conn1] [QLOG] Index 7:

{ username: 1 }

2014-04-23T16:36:35.523+0200 [conn1] [QLOG] Index 8:

{ eventtype: 1 }

2014-04-23T16:36:35.523+0200 [conn1] [QLOG] Index 9:

{ email: 1 }

2014-04-23T16:36:35.523+0200 [conn1] [QLOG] Index 10:

{ clientid: 1 }

2014-04-23T16:36:35.523+0200 [conn1] [QLOG] Index 11:

{ time: 1 }

2014-04-23T16:36:35.523+0200 [conn1] [QLOG] Index 12:

{ campaign: 1 }

2014-04-23T16:36:35.523+0200 [conn1] [QLOG] Index 13:

{ messageid: 1 }

2014-04-23T16:36:35.523+0200 [conn1] [QLOG] Index 14:

{ running: 1 }

2014-04-23T16:36:35.523+0200 [conn1] [QLOG] Index 15:

{ folder: -1, filename: -1 }

2014-04-23T16:36:35.524+0200 [conn1] [QLOG] Index 16:

{ timestamp: -1 }

2014-04-23T16:36:35.524+0200 [conn1] [QLOG] Index 17:

{ enabled: 1 }

2014-04-23T16:36:35.524+0200 [conn1] [QLOG] Index 18:

{ send_date: 1 }

2014-04-23T16:36:35.524+0200 [conn1] [QLOG] Index 19:

{ company: 1 }

2014-04-23T16:36:35.524+0200 [conn1] [QLOG] Index 20:

{ invoiceid: 1 }

2014-04-23T16:36:35.524+0200 [conn1] [QLOG] Index 21:

{ creditid: 1 }

2014-04-23T16:36:35.524+0200 [conn1] [QLOG] Index 22:

{ fingerprint: 1 }

2014-04-23T16:36:35.524+0200 [conn1] [QLOG] Index 23:

{ archive: 1 }

2014-04-23T16:36:35.524+0200 [conn1] [QLOG] Index 24:

{ type: 1, folder: 1, geometry: "2dsphere" }

2014-04-23T16:36:35.524+0200 [conn1] [QLOG] Index 25:

{ folder: 1, type: 1, active: 1 }

2014-04-23T16:36:35.524+0200 [conn1] [QLOG] Index 26:

{ client: 1 }

2014-04-23T16:36:35.524+0200 [conn1] [QLOG] Index 27:

{ options.orderid: 1 }

2014-04-23T16:36:35.524+0200 [conn1] [QLOG] Index 28:

{ type: 1, folder: 1, timestamp: -1 }

2014-04-23T16:36:35.524+0200 [conn1] [QLOG] Index 29:

{ campaign_date_started: 1 }

2014-04-23T16:36:35.524+0200 [conn1] [QLOG] Index 30:

{ fulltext: 1 }

2014-04-23T16:36:35.524+0200 [conn1] [QLOG] Index 31:

{ to.email: 1 }

2014-04-23T16:36:35.524+0200 [conn1] [QLOG] Tagged tree:
2014-04-23T16:36:35.524+0200 [conn1] [QLOG] Planner: solution constructed from the cache:
2014-04-23T16:36:35.524+0200 [conn1] Using cached query plan: query:

{ type: "folder", folder: /^((^|\/)[^\/\.][^\/]*)$/ }

sort: {} projection: {}, planSummary: IXSCAN

{ type: 1 }

2014-04-23T16:36:38.997+0200 [conn1] [QLOG] score(1.00031) = baseScore(1) + productivity((20 advanced)/(2005268 works + 0 needFetch) = 9.97373e-06) + tieBreakers(0.0001 noFetchBonus + 0.0001 noSortBonus + 0.0001 noIxisectBonus = 0.0003)
2014-04-23T16:36:38.997+0200 [conn1] score(1.00031) = baseScore(1) + productivity((20 advanced)/(2005268 works + 0 needFetch) = 9.97373e-06) + tieBreakers(0.0001 noFetchBonus + 0.0001 noSortBonus + 0.0001 noIxisectBonus = 0.0003)
2014-04-23T16:36:38.997+0200 [conn1] [QLOG] Not caching runner but returning 20 results.
2014-04-23T16:36:38.997+0200 [conn1] query edison.fs query:

{ type: "folder", folder: /^((^|\/)[^\/\.][^\/]*)$/ }

planSummary: IXSCAN

{ type: 1 }

ntoreturn:0 ntoskip:0 nscanned:2005267 nscannedObjects:2005267 keyUpdates:0 numYields:3 locks(micros) r:6196619 nreturned:20 reslen:1954 3474ms
2014-04-23T16:36:39.003+0200 [conn1] run command edison.$cmd

{ isMaster: 1.0, forShell: 1.0 }

2014-04-23T16:36:39.003+0200 [conn1] command edison.$cmd command: isMaster

{ isMaster: 1.0, forShell: 1.0 }

keyUpdates:0 numYields:0 reslen:178 0ms

Comment by David Storch [ 23/Apr/14 ]

I was hoping for the logLevel 2 and verboseQueryLogging output from 2.6.0 (not 2.4), apologies for being unclear about that. If possible, please attach the logging from a 2.6.0 server.

That said, we have been able to reproduce a very similar problem locally with a toy data set, so I have a strong hypothesis about what the problem is. The plan ranker chooses plans by "racing" them against each other and choosing the one that produces the most results in the least amount of work. The good plan, which uses the compound index on "type" and "folder", appears to be producing results at the same rate as the bad plan, which uses the index on just "type". As a result, the plans tie and we arbitrarily choose one (just happening to end up with the bad plan).

One possible fix is to break ties by measuring the selectivity of the index scan. What distinguishes the good plan from the bad plan is that the good plan has a much more selective index scan, and hence has to fetch fewer full documents.

Thanks again rgpublic for letting us know about this issue!

Comment by rgpublic [ 23/Apr/14 ]

Do you need the logging with the old or new Mongo version. I've made a copy on a second server where I can test without messing anything up and switch between versions at will. I'm currently on 2.4.10.

runCommand(

{setParameter: 1, verboseQueryLogging: true}

); doesn't seem to work there. It says:

no option found to set, use help:true to see options.

Loglevel 2 works. What log results do you need now? For the relevant connection I find in /var/log/mongodb/mongodb.log the following:

  1. tail -f /var/log/mongodb/mongodb.log | grep conn3
    Wed Apr 23 15:14:05.713 [conn3] runQuery called admin.$cmd { replSetGetStatus: 1.0, forShell: 1.0 }

    Wed Apr 23 15:14:05.713 [conn3] run command admin.$cmd

    { replSetGetStatus: 1.0, forShell: 1.0 }

    Wed Apr 23 15:14:05.713 [conn3] command:

    { replSetGetStatus: 1.0, forShell: 1.0 }

    Wed Apr 23 15:14:05.713 [conn3] command admin.$cmd command:

    { replSetGetStatus: 1.0, forShell: 1.0 }

    ntoreturn:1 keyUpdates:0 reslen:76 0ms
    Wed Apr 23 15:14:05.837 [conn3] runQuery called admin.$cmd

    { replSetGetStatus: 1.0, forShell: 1.0 }

    Wed Apr 23 15:14:05.838 [conn3] run command admin.$cmd

    { replSetGetStatus: 1.0, forShell: 1.0 }

    Wed Apr 23 15:14:05.838 [conn3] command:

    { replSetGetStatus: 1.0, forShell: 1.0 }

    Wed Apr 23 15:14:05.838 [conn3] command admin.$cmd command:

    { replSetGetStatus: 1.0, forShell: 1.0 }

    ntoreturn:1 keyUpdates:0 reslen:76 0ms
    Wed Apr 23 15:14:05.954 [conn3] runQuery called admin.$cmd

    { replSetGetStatus: 1.0, forShell: 1.0 }

    Wed Apr 23 15:14:05.954 [conn3] run command admin.$cmd

    { replSetGetStatus: 1.0, forShell: 1.0 }

    Wed Apr 23 15:14:05.954 [conn3] command:

    { replSetGetStatus: 1.0, forShell: 1.0 }

    Wed Apr 23 15:14:05.973 [conn3] command admin.$cmd command:

    { replSetGetStatus: 1.0, forShell: 1.0 }

    ntoreturn:1 keyUpdates:0 reslen:76 0ms
    Wed Apr 23 15:14:06.061 [conn3] runQuery called admin.$cmd

    { replSetGetStatus: 1.0, forShell: 1.0 }

    Wed Apr 23 15:14:06.061 [conn3] run command admin.$cmd

    { replSetGetStatus: 1.0, forShell: 1.0 }

    Wed Apr 23 15:14:06.061 [conn3] command:

    { replSetGetStatus: 1.0, forShell: 1.0 }

    Wed Apr 23 15:14:06.061 [conn3] command admin.$cmd command:

    { replSetGetStatus: 1.0, forShell: 1.0 }

    ntoreturn:1 keyUpdates:0 reslen:76 0ms
    Wed Apr 23 15:14:06.189 [conn3] runQuery called admin.$cmd

    { replSetGetStatus: 1.0, forShell: 1.0 }

    Wed Apr 23 15:14:06.189 [conn3] run command admin.$cmd

    { replSetGetStatus: 1.0, forShell: 1.0 }

    Wed Apr 23 15:14:06.189 [conn3] command:

    { replSetGetStatus: 1.0, forShell: 1.0 }

    Wed Apr 23 15:14:06.189 [conn3] command admin.$cmd command:

    { replSetGetStatus: 1.0, forShell: 1.0 }

    ntoreturn:1 keyUpdates:0 reslen:76 0ms
    Wed Apr 23 15:14:06.654 [conn3] runQuery called edison.fs

    { type: "folder", folder: /^((^|\/)[^\/\.][^\/]*)$/ }

    Wed Apr 23 15:14:10.105 [conn3] query edison.fs query:

    { type: "folder", folder: /^((^|\/)[^\/\.][^\/]*)$/ }

    ntoreturn:0 ntoskip:0 nscanned:2005267 keyUpdates:0 numYields: 4 locks(micros) r:6829374 nreturned:20 reslen:1954 3451ms
    Wed Apr 23 15:14:10.112 [conn3] runQuery called admin.$cmd

    { replSetGetStatus: 1.0, forShell: 1.0 }

    Wed Apr 23 15:14:10.112 [conn3] run command admin.$cmd

    { replSetGetStatus: 1.0, forShell: 1.0 }

    Wed Apr 23 15:14:10.112 [conn3] command:

    { replSetGetStatus: 1.0, forShell: 1.0 }

    Wed Apr 23 15:14:10.112 [conn3] command admin.$cmd command:

    { replSetGetStatus: 1.0, forShell: 1.0 }

    ntoreturn:1 keyUpdates:0 reslen:76 0ms

Don't know if there's anything valuable for you in there. Let me know if you need more/other logs.

Comment by David Storch [ 22/Apr/14 ]

Thanks for the info rgpublic. I can't be sure what's going on yet, but the additional logging should be illuminating. Another thing that might be helpful for us in addition to logLevel 2 is enabling verbose query logging, an internal debug logging mechanism for the query planner and ranker. Before running your query, you can enable verbose query logging with

runCommand({setParameter: 1, verboseQueryLogging: true});

and then disable it afterwords with

runCommand({setParameter: 1, verboseQueryLogging: false});

This is even more verbose than log level 2 so it comes with an even stronger warning, namely that it should only be run in a test environment that is not under load.

Comment by rgpublic [ 22/Apr/14 ]

1.) Did you really mean find() without the query (i.e. all rows)? If so, this is it:

> db.fs.find().limit(10).pretty()
{
"_id" : ObjectId("4ece5773b86496e202000000"),
"folder" : "users",
"sortindex" : 0,
"type" : "folder"
}
{
"_id" : ObjectId("4ece588cb864963a04000002"),
"filename" : "U00000.pro",
"folder" : "users",
"password" : "[removed here for security reasons, but basically a very long hex-character string (hash)]",
"sortindex" : 9,
"type" : "file",
"username" : "admin"
}
{
"_id" : ObjectId("4ece5aecb86496530a000000"),
"type" : "folder",
"folder" : ""
}
{
"_id" : ObjectId("4ece5fe8b864965e0f000000"),
"type" : "folder",
"folder" : ".folder/realms"
}
{
"_id" : ObjectId("4ece5fe8b864965e0f000001"),
"type" : "folder",
"folder" : ".folder/realms/.^icons.file.pro/sets"
}
{
"_id" : ObjectId("4ece5fe8b864965e0f000002"),
"type" : "folder",
"folder" : ".folder/realms/.^icons.file.pro/sets/.default.pro/fields"
}
{
"_id" : ObjectId("4ece5fe8b864965e0f000003"),
"type" : "folder",
"folder" : ".folder/realms/.^realms.file.pro/icon"
}
{
"_id" : ObjectId("4ece5fe8b864965e0f000004"),
"type" : "folder",
"folder" : ".folder/realms/.^realms.file.pro/sets"
}
{
"_id" : ObjectId("4ece5fe8b864965e0f000005"),
"type" : "folder",
"folder" : ".folder/realms/.^realms.file.pro/sets/.default.pro"
}
{
"_id" : ObjectId("4ece5fe8b864965e0f000006"),
"type" : "folder",
"folder" : ".folder/realms/.^realms.file.pro/sets/.default.pro/fields"
}

2.) > db.fs.find().count()
15053988

3.) Our data is basically a huge (15 mio records) table which you can think of like some kind of virtual file system (that is consists of files and folders). The key "type" can only ever be "file" or "folder". The key "folder" is always path much like a UNIX file path. Records of type "file" additionally a "filename" property that saves the filename. The problematic query tries to find the first level non-hidden folders (the regex could obviously be simplified but is automatically generated for various use cases and depths)

4.) Will try this tomorrow and post the results here

Comment by David Storch [ 22/Apr/14 ]

Hi rgpublic, the plan ranker appears to be choosing an inefficient plan. The decisions made by the ranker are highly dependent on the structure of your data. In order to diagnose the problem, could you:

  1. Paste in the output of find().limit(10).pretty() on your collection.
  2. Paste in the output of find().count() on your collection.
  3. Provide any other information about your data. The more we know about what the collection looks like, the easier it will be to determine why the ranker made the bad plan choice.
  4. If possible, enable log level 2 using the command runCommand({setParameter: 1, logLevel: 2}) and then provide the log output after running the query. This is a verbose log level which should only be enabled in a testing environment. You can restore the default verbosity afterwards with runCommand({setParameter: 1, logLevel: 0}).

Thanks very much for your help on this,

Dave

Comment by rgpublic [ 22/Apr/14 ]

Yes, it's the same database. I just switched between both versions back and forth with apt-get (Ubuntu). explain(true) on the command live gives the same explain plan for 2.4 as my explain plan in the original bug report above. I've created the latter with RockMongo - it uses the verbose argument by default, I suppose. getIndexes() result below.

> db.fs.getIndexes()
[
        {
                "v" : 1,
                "key" : {
                        "_id" : 1
                },
                "ns" : "edison.fs",
                "name" : "_id_"
        },
        {
                "v" : 1,
                "key" : {
                        "filename" : 1
                },
                "ns" : "edison.fs",
                "background" : 1,
                "name" : "filename"
        },
        {
                "v" : 1,
                "key" : {
                        "folder" : 1
                },
                "ns" : "edison.fs",
                "background" : 1,
                "name" : "folder"
        },
        {
                "v" : 1,
                "key" : {
                        "type" : 1
                },
                "ns" : "edison.fs",
                "background" : 1,
                "name" : "type"
        },
        {
                "v" : 1,
                "key" : {
                        "binary_id" : 1
                },
                "ns" : "edison.fs",
                "background" : 1,
                "name" : "binary_id"
        },
        {
                "v" : 1,
                "key" : {
                        "sessionid" : 1
                },
                "ns" : "edison.fs",
                "background" : 1,
                "name" : "sessionid"
        },
        {
                "v" : 1,
                "key" : {
                        "type" : 1,
                        "folder" : 1
                },
                "ns" : "edison.fs",
                "background" : 1,
                "name" : "type_folder"
        },
        {
                "v" : 1,
                "key" : {
                        "username" : 1
                },
                "ns" : "edison.fs",
                "background" : 1,
                "name" : "username"
        },
        {
                "v" : 1,
                "key" : {
                        "eventtype" : 1
                },
                "ns" : "edison.fs",
                "background" : 1,
                "name" : "eventtype"
        },
        {
                "v" : 1,
                "key" : {
                        "email" : 1
                },
                "ns" : "edison.fs",
                "background" : 1,
                "name" : "email"
        },
        {
                "v" : 1,
                "key" : {
                        "clientid" : 1
                },
                "ns" : "edison.fs",
                "background" : 1,
                "name" : "clientid"
        },
        {
                "v" : 1,
                "key" : {
                        "time" : 1
                },
                "ns" : "edison.fs",
                "background" : 1,
                "name" : "time"
        },
        {
                "v" : 1,
                "key" : {
                        "campaign" : 1
                },
                "ns" : "edison.fs",
                "background" : 1,
                "name" : "campaign"
        },
        {
                "v" : 1,
                "key" : {
                        "messageid" : 1
                },
                "ns" : "edison.fs",
                "background" : 1,
                "name" : "messageid"
        },
        {
                "v" : 1,
                "key" : {
                        "running" : 1
                },
                "ns" : "edison.fs",
                "background" : 1,
                "name" : "running"
        },
        {
                "v" : 1,
                "key" : {
                        "folder" : -1,
                        "filename" : -1
                },
                "ns" : "edison.fs",
                "background" : 1,
                "name" : "folder_filename_desc"
        },
        {
                "v" : 1,
                "key" : {
                        "timestamp" : -1
                },
                "ns" : "edison.fs",
                "background" : 1,
                "name" : "timestamp"
        },
        {
                "v" : 1,
                "key" : {
                        "enabled" : 1
                },
                "ns" : "edison.fs",
                "background" : 1,
                "name" : "enabled"
        },
        {
                "v" : 1,
                "key" : {
                        "send_date" : 1
                },
                "ns" : "edison.fs",
                "background" : 1,
                "name" : "send_date"
        },
        {
                "v" : 1,
                "key" : {
                        "company" : 1
                },
                "ns" : "edison.fs",
                "background" : 1,
                "name" : "company"
        },
        {
                "v" : 1,
                "key" : {
                        "invoiceid" : 1
                },
                "ns" : "edison.fs",
                "background" : 1,
                "name" : "invoiceid"
        },
        {
                "v" : 1,
                "key" : {
                        "creditid" : 1
                },
                "ns" : "edison.fs",
                "background" : 1,
                "name" : "creditid"
        },
        {
                "v" : 1,
                "key" : {
                        "fingerprint" : 1
                },
                "ns" : "edison.fs",
                "background" : 1,
                "name" : "fingerprint"
        },
        {
                "v" : 1,
                "key" : {
                        "archive" : 1
                },
                "ns" : "edison.fs",
                "background" : 1,
                "name" : "archive"
        },
        {
                "v" : 1,
                "key" : {
                        "type" : 1,
                        "folder" : 1,
                        "geometry" : "2dsphere"
                },
                "ns" : "edison.fs",
                "name" : "type_1_folder_1_geometry_2dsphere"
        },
        {
                "v" : 1,
                "key" : {
                        "folder" : 1,
                        "type" : 1,
                        "active" : 1
                },
                "ns" : "edison.fs",
                "background" : 1,
                "name" : "folder_type_active"
        },
        {
                "v" : 1,
                "key" : {
                        "client" : NumberLong(1)
                },
                "ns" : "edison.fs",
                "background" : NumberLong(1),
                "name" : "client"
        },
        {
                "v" : 1,
                "key" : {
                        "options.orderid" : NumberLong(1)
                },
                "ns" : "edison.fs",
                "background" : NumberLong(1),
                "name" : "options_orderid"
        },
        {
                "v" : 1,
                "key" : {
                        "type" : NumberLong(1),
                        "folder" : NumberLong(1),
                        "timestamp" : NumberLong(-1)
                },
                "ns" : "edison.fs",
                "background" : NumberLong(1),
                "name" : "type_folder_timestamp_desc"
        },
        {
                "v" : 1,
                "key" : {
                        "campaign_date_started" : NumberLong(1)
                },
                "ns" : "edison.fs",
                "background" : NumberLong(1),
                "name" : "campaign_date_started"
        },
        {
                "v" : 1,
                "name" : "fulltext",
                "key" : {
                        "fulltext" : NumberLong(1)
                },
                "ns" : "edison.fs",
                "background" : NumberLong(1)
        },
        {
                "v" : 1,
                "name" : "to_email",
                "key" : {
                        "to.email" : NumberLong(1)
                },
                "ns" : "edison.fs",
                "background" : NumberLong(1)
        }
]

Comment by Asya Kamsky [ 22/Apr/14 ]

Do you have the same indexes in both tests? Can you include full explain(true) from 2.4? Also db.collection.getIndexes()

Comment by rgpublic [ 22/Apr/14 ]

Interestingly, I just realized that the correct plan (type_folder) even shows up under "All plans" with 2.6. nscannedObjects=20. But instead it prefers to scan 2005419 objects. Sigh.

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