I've created a collection with 100k entries like:
{ a: <int>, b: <int>, c: <int>, txt: <5k string> }
And query with:
> db.foo.find({a: {$lt: 32065}, b: 23})
Explain shows this:
{
"cursor" : "BasicCursor",
"nscanned" : 100000,
"nscannedObjects" : 100000,
"n" : 211,
"millis" : 140,
"nYields" : 0,
"nChunkSkips" : 0,
"isMultiKey" : false,
"indexOnly" : false,
"indexBounds" : {
}
}
But system.profile shows this:
{
"ts" : ISODate("2011-09-20T17:25:19.664Z"),
"op" : "query",
"ns" : "test.foo",
"query" : {
"query" : {
"a" : {
"$lt" : 32065
},
"b" : 23
},
"$explain" : true
},
"nscanned" : 100000,
"nreturned" : 1,
"responseLength" : 297,
"millis" : 0,
"client" : "127.0.0.1",
"user" : ""
}
With profiling level set to 1, the output in system.profile reflects the correct millis. The profile output in 1.8.3 is correct:
{
"ts" : ISODate("2011-09-20T17:24:37.464Z"),
"info" : "query example.bigdocs reslen:313 nscanned:100000 \nquery: { query: { a: { $lt: 32065.0 }, b: 23.0 }, $explain: true } nreturned:1 bytes:297",
"millis" : 56
}
(Note that this behavior is true with or without .explain(), I only used that to find out the actual millis to execute the query)