[SERVER-8539] Profiler omits operations which don't acquire a database lock Created: 12/Feb/13  Updated: 06/Dec/22  Resolved: 21/Mar/16

Status: Closed
Project: Core Server
Component/s: Diagnostics
Affects Version/s: 2.4.0-rc0, 2.6.3
Fix Version/s: None

Type: Bug Priority: Minor - P4
Reporter: Derick Rethans Assignee: Backlog - Storage Execution Team
Resolution: Duplicate Votes: 1
Labels: neweng, profiling
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
duplicates SERVER-21855 Certain commands are never captured i... Backlog
Assigned Teams:
Storage Execution
Operating System: ALL
Participants:

 Description   

When implementing PHP-490, I noticed that the profile log (in db.system.profile) does not record when an $eval command is run with the "nolock" : true option set. To reproduce:

> db.setProfilingLevel(2);
{ "was" : 2, "slowms" : 100, "ok" : 1 }
> db.runCommand({$eval: function(x,y) {return x*y;}, args: [6,7], nolock: true})
{ "retval" : 42, "ok" : 1 }
> db.system.profile.find( { op: { $ne: "query" } }).sort( { 'ts' : -1 }).limit(3).pretty();
{
	"op" : "command",
	"ns" : "phpunit.$cmd",
	"command" : {
		"profile" : 2
	},
	"ntoreturn" : 1,
	"keyUpdates" : 0,
	"numYield" : 0,
	"lockStats" : {
		"timeLockedMicros" : {
			"r" : NumberLong(0),
			"w" : NumberLong(15)
		},
		"timeAcquiringMicros" : {
			"r" : NumberLong(0),
			"w" : NumberLong(7)
		}
	},
	"responseLength" : 58,
	"millis" : 0,
	"ts" : ISODate("2013-02-12T21:53:54.364Z"),
	"client" : "127.0.0.1",
	"allUsers" : [ ],
	"user" : ""
}

As you can see, the only entry in the profile log is enabling the profile. If we use nolock : false, the $eval command does show up:

> db.runCommand({$eval: function(x,y) {return x*y;}, args: [6,7], nolock: false})
{ "retval" : 42, "ok" : 1 }
> db.system.profile.find( { op: { $ne: "query" } }).sort( { 'ts' : -1 }).limit(3).pretty();
{
	"op" : "command",
	"ns" : "phpunit.$cmd",
	"command" : {
		"$eval" : function __cf__2__f__anonymous_function(x, y) {
    return x * y;
},
		"args" : [
			6,
			7
		],
		"nolock" : false
	},
	"ntoreturn" : 1,
	"keyUpdates" : 0,
	"numYield" : 0,
	"lockStats" : {
		"timeLockedMicros" : {
			"R" : NumberLong(0),
			"W" : NumberLong(126)
		},
		"timeAcquiringMicros" : {
			"R" : NumberLong(0),
			"W" : NumberLong(2),
			"r" : NumberLong(0),
			"w" : NumberLong(4)
		}
	},
	"responseLength" : 53,
	"millis" : 0,
	"ts" : ISODate("2013-02-12T21:54:23.620Z"),
	"client" : "127.0.0.1",
	"allUsers" : [ ],
	"user" : ""
}
{
	"op" : "command",
	"ns" : "phpunit.$cmd",
	"command" : {
		"profile" : 2
	},
	"ntoreturn" : 1,
	"keyUpdates" : 0,
	"numYield" : 0,
	"lockStats" : {
		"timeLockedMicros" : {
			"r" : NumberLong(0),
			"w" : NumberLong(15)
		},
		"timeAcquiringMicros" : {
			"r" : NumberLong(0),
			"w" : NumberLong(7)
		}
	},
	"responseLength" : 58,
	"millis" : 0,
	"ts" : ISODate("2013-02-12T21:53:54.364Z"),
	"client" : "127.0.0.1",
	"allUsers" : [ ],
	"user" : ""
}



 Comments   
Comment by J Rassi [ 21/Mar/16 ]

Closing as a dup of SERVER-21855.

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