In the Mongo logs, I noticed that some queries take 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
Given that I built the index on {someField: 1, "lastRecord.otherValue": 1, "lastRecord.importantValue": -1} I went to investigate.
During this, I noticed that what looks like two identical queries for me, just formulated differently syntactically and that returns identical values, is performed differently by MongoDB - one uses the index as expected, and the other does not.
And my web application calls a version that does not use indexes.
I obviously misunderstand something fundamental here.
The pointer is used perfectly:
> 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" }
The pointer is 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, the return values are the same (e.g. 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) }
A pointer is present (this one I created to test for simpler queries, a composite index also still exists):
> db.User.getIndexes() [ // snip other indexes { "v" : 1, "key" : { "lastRecord.importantValue" : -1 }, "ns" : "mydb.User", "name" : "lastRecord.importantValue_-1" } ]
Morphia code is just FYI (not sure if I can get the exact command that 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 January 6th:
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. Since then I have removed $ ne from the request. Thus, it runs in 118 ms and (if I interpret correctly) scans only 2042 lines.
However, if I do the following from the 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 this just be a mistake in explanation?
Edit - further update January 6th:
On the other hand, my local system (the same indexes, including "{someField: 1," lastRecord.otherValue ": 1," lastRecord.importantValue ": -1}") I managed to get 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 : (