[SERVER-3910] millis always 0 when profilingLevel is 2 Created: 20/Sep/11  Updated: 11/Jul/16  Resolved: 03/Oct/11

Status: Closed
Project: Core Server
Component/s: Logging
Affects Version/s: 2.0.0
Fix Version/s: 2.0.1, 2.1.0

Type: Bug Priority: Minor - P4
Reporter: Daniel Crosta Assignee: Eliot Horowitz (Inactive)
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Operating System: OS X
Participants:

 Description   

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)



 Comments   
Comment by auto [ 03/Oct/11 ]

Author:

{u'login': u'erh', u'name': u'Eliot Horowitz', u'email': u'eliot@10gen.com'}

Message: setProfilingLevel(2) not always working because millis set in wrong place SERVER-3910
Branch: v2.0
https://github.com/mongodb/mongo/commit/4063312d6044196be67fd29c6daac8768f6f6110

Comment by auto [ 03/Oct/11 ]

Author:

{u'login': u'erh', u'name': u'Eliot Horowitz', u'email': u'eliot@10gen.com'}

Message: test for SERVER-3910
Branch: master
https://github.com/mongodb/mongo/commit/2ce2b1aba261abc5e6cefa09b6b4d6796b5f44e3

Comment by auto [ 03/Oct/11 ]

Author:

{u'login': u'erh', u'name': u'Eliot Horowitz', u'email': u'eliot@10gen.com'}

Message: setProfilingLevel(2) not always working because millis set in wrong place SERVER-3910
Branch: master
https://github.com/mongodb/mongo/commit/96a765d41ca880f42e7ff0caeceaafb771918d8b

Comment by Daniel Crosta [ 20/Sep/11 ]

Workaround:

Rather than:

db.setProfilingLevel(2)

use:

db.runCommand({profile: 1, slowms: 0})

Then the correct millis is reported in system.profile.

Generated at Thu Feb 08 03:04:24 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.