Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-3910

millis always 0 when profilingLevel is 2

    • Type: Icon: Bug Bug
    • Resolution: Done
    • Priority: Icon: Minor - P4 Minor - P4
    • 2.0.1, 2.1.0
    • Affects Version/s: 2.0.0
    • Component/s: Logging
    • Labels:
      None
    • OS X

      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)

            Assignee:
            eliot Eliot Horowitz (Inactive)
            Reporter:
            dcrosta Daniel Crosta
            Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

              Created:
              Updated:
              Resolved: