MongoDB two seemingly identical queries - one uses an index the other doesn't

Question

I noticed in Mongo logs that some queries were taking longer than expected.

Fri Jan  4 08:53:39 [conn587] query mydb.User query: { query: { someField: "eu", lastRecord.importantValue: { $ne: nan.0 }, lastRecord.otherValue: { $gte: 1000 } }, orderby: { lastRecord.importantValue: -1 } } ntoreturn:50 ntoskip:0 nscanned:40681 scanAndOrder:1 keyUpdates:0 numYields: 1 locks(micros) r:2649788 nreturned:50 reslen:334041 1575ms

Considering that I had built an index on {someField : 1, "lastRecord.otherValue" : 1, "lastRecord.importantValue" : -1} I went to investigate.

During that I noticed that what seem like two identical queries to me, just phrased differently syntactically and what return identical values, are executed differently by MongoDB - one uses the index as expected, while the other doesn't.

And my web application invokes the version that doesn't use indexes.

I'm obviously misunderstanding something fundamental here.

Index used fine:

> db.User.find({}, {_id:1}).sort({"lastRecord.importantValue" : -1}).limit(5).explain()
{
    "cursor" : "BtreeCursor lastRecord.importantValue_-1",
    "isMultiKey" : false,
    "n" : 5,
    "nscannedObjects" : 5,
    "nscanned" : 5,
    "nscannedObjectsAllPlans" : 5,
    "nscannedAllPlans" : 5,
    "scanAndOrder" : false,
    "indexOnly" : false,
    "nYields" : 0,
    "nChunkSkips" : 0,
    "millis" : 0,
    "indexBounds" : {
            "lastRecord.importantValue" : [
                    [
                            {
                                    "$maxElement" : 1
                            },
                            {
                                    "$minElement" : 1
                            }
                    ]
            ]
    },
    "server" : "whatever"
}

Index not used:

> db.User.find({$query: {}, $orderby : {"lastRecord.importantValue": -1}}, {_id:1}).limit(5).explain()
{
    "cursor" : "BasicCursor",
    "isMultiKey" : false,
    "n" : 0,
    "nscannedObjects" : 67281,
    "nscanned" : 67281,
    "nscannedObjectsAllPlans" : 67281,
    "nscannedAllPlans" : 67281,
    "scanAndOrder" : false,
    "indexOnly" : false,
    "nYields" : 0,
    "nChunkSkips" : 0,
    "millis" : 133,
    "indexBounds" : {

    },
    "server" : "whatever"
}

Hint doesn't help:

> db.User.find({$query: {}, $orderby : {"lastRecord.importantValue": -1}, $hint : {"lastRecord.importantValue" : -1}}, {_id:1}).limit(5).explain()
{
    "cursor" : "BasicCursor",
    // snip
}

However returned values are same (like expected):

> db.User.find({}, {_id:1}).sort({"lastRecord.importantValue" : -1}).limit(5)
{ "_id" : NumberLong(500280899) }
{ "_id" : NumberLong(500335132) }
{ "_id" : NumberLong(500378261) }
{ "_id" : NumberLong(500072584) }
{ "_id" : NumberLong(500071366) }

> db.User.find({$query: {}, $orderby : {"lastRecord.importantValue": -1}}, {_id:1}).limit(5)
{ "_id" : NumberLong(500280899) }
{ "_id" : NumberLong(500335132) }
{ "_id" : NumberLong(500378261) }
{ "_id" : NumberLong(500072584) }
{ "_id" : NumberLong(500071366) }

Index is present (this one I created to test the simpler queries, the compound index is also still there):

> db.User.getIndexes()
[
// snip other indexes

    {
            "v" : 1,
            "key" : {
                    "lastRecord.importantValue" : -1
            },
            "ns" : "mydb.User",
            "name" : "lastRecord.importantValue_-1"
    }
]

Morphia code just FYI (not sure if I can get exact command it generates):

        ds.find(User.class).filter("someField =", v1)
                .filter("lastRecord.importantValue !=", Double.NaN)
                .filter("lastRecord.otherValue >=", v2)
                .order("-lastRecord.importantValue")
                .limit(50);

Any ideas?

Edit 6-Jan:

Just noticed another instance of this in the logs:

TOKEN ip-10-212-234-60 Sun Jan  6 09:20:54 [conn249] query mydb.User query: { query: { someField: "eu", lastRecord.otherValue: { $gte: 1000 } }, orderby: { lastRecord.importantValue: -1 } } cursorid:9069510232503855502 ntoreturn:50 ntoskip:0 nscanned:2042 keyUpdates:0 locks(micros) r:118923 nreturned:50 reslen:344959 118ms 

Note I have since removed the $ne from the query. So it executes in 118 ms and (if I interpret right) scans 2042 rows only.

However if I do the following from console on the same server:

> db.User.find({$query: { someField: "eu", "lastRecord.otherValue": { $gte: 1000 } }, $orderby: { "lastRecord.importantValue": -1 } }).explain()
{
 "cursor" : "BasicCursor",
 "isMultiKey" : false,
 "n" : 0,
 "nscannedObjects" : 70308,
 "nscanned" : 70308,
 "nscannedObjectsAllPlans" : 70308,
 "nscannedAllPlans" : 70308,
 "scanAndOrder" : false,
 "indexOnly" : false,
 "nYields" : 1,
 "nChunkSkips" : 0,
 "millis" : 847,
 "indexBounds" : {

 },
 "server" : "ip-whatever:27017"
}

So could it really be just a bug in explain?

Edit - further update 6-Jan:

On the other hand on my local system (same indexes, including "{someField : 1, "lastRecord.otherValue" : 1, "lastRecord.importantValue" : -1}") I managed to obtain the following under load:

Sun Jan 06 17:43:56 [conn33] query mydb.User query: { query: { someField: "eu", lastRecord.otherValue: { $gte: 1000 } }, orderby: { lastRecord.importantValue: -1 } } 
cursorid:76077040284571 ntoreturn:50 ntoskip:0 nscanned:183248 keyUpdates:0 numYields: 2318 locks(micros) r:285016301 nreturned:50 reslen:341500 148567ms

148567ms :(

Answer 1

In fact the problem is mixing up the two syntax.

According to the documentation : http://docs.mongodb.org/manual/reference/operator/query/

So when you use .explain in :

db.User.find({}, {_id:1}).sort({"lastRecord.importantValue" : -1}).limit(5).explain()

fine but when you use this :

db.User.find({$query: {}, $orderby : {"lastRecord.importantValue": -1}}, {_id:1}).limit(5).explain()

Explain is used in the first type of syntax : you should use $explain:1 inside the $query and not .explain after.

See this question also : MongoDB $query operator ignores index?

It is quite about the same issue.