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 :(

I wonder if this is a bug in the explain actually, i.e. the query that didn't use an index said that `n` was `0` yet you clearly saw that when you ran the query it did return results. The `order()` command in Morphia should be ok though. On this I am getting the exact same berhaviour on 2.0 — Sammaye, Jan 04 '13 at 12:26
Agreed the second explain looks odd .. `n=0` and empty `indexBounds`. What specific version of MongoDB are you using? Irrespective of MongoDB version, I suspect the problem with your original query is the use of `$ne`: `lastRecord.importantValue: { $ne: nan.0 }`. If this isn't a very selective query it may be faster to find documents using a table scan than the index. The MongoDB documentation has an FAQ point on this and links to more indexing tips: [Using $ne and $nin in a query is slow. Why?](http://docs.mongodb.org/manual/faq/indexes/#using-ne-and-nin-in-a-query-is-slow-why). — Stennie, Jan 04 '13 at 14:08
I run db version v2.2.2, pdfile version 4.5 Fri Jan 4 14:59:40 git version: d1b43b61a5308c4ad0679d34b262c5af9d664267. I will try to get rid of the $ne. I'm just not sure how NaNs are sorted when compared to other normal doubles. Google App Engine datastore had them as larger as all doubles which broke the report. — John M, Jan 04 '13 at 15:01
I don't think it is just a bug in .explain() as it seemed the query which according to explain didn't use the index did run slower than the one which did. Both are fast enough that I could be wrong. — John M, Jan 04 '13 at 15:11
Note that while the `$orderby` operator is part of the query, `.sort` is a function on the database cursor returned by the query. — Philipp, Jan 06 '13 at 17:57
Philipp, I was pondering that, but I'm not sure what are the implications of that, especially for index selection. Would $orderby generally be more efficient? — John M, Jan 06 '13 at 19:26

score 2 · Accepted Answer · edited Jun 20 '20 at 09:12

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.

Thanks for the explanation, I'm running some tests but you appear to be completely right. — John M, May 30 '13 at 14:50

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

1 Answers1