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

Profiler omits operations which don't acquire a database lock

    • Type: Icon: Bug Bug
    • Resolution: Duplicate
    • Priority: Icon: Minor - P4 Minor - P4
    • None
    • Affects Version/s: 2.4.0-rc0, 2.6.3
    • Component/s: Diagnostics
    • Storage Execution
    • ALL

      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" : ""
      }
      

            Assignee:
            backlog-server-execution [DO NOT USE] Backlog - Storage Execution Team
            Reporter:
            derick Derick Rethans
            Votes:
            1 Vote for this issue
            Watchers:
            7 Start watching this issue

              Created:
              Updated:
              Resolved: