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)