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

Incorrect nscanned and nscannedObjects for idhack updates in 2.6.4 profiler or slow query log

XMLWordPrintableJSON

    • Type: Icon: Bug Bug
    • Resolution: Done
    • Priority: Icon: Major - P3 Major - P3
    • 2.6.5
    • Affects Version/s: 2.6.4
    • Component/s: Write Ops
    • Labels:
      None
    • Fully Compatible
    • ALL
    • Hide
      1. Start a standalone mongod using 2.6.4
      2. Insert a document: 
        > db.t.insert( { _id :1, x : 1 } )
WriteResult({ "nInserted" : 1 })
      3. Enable profiling: 
        > db.setProfilingLevel(2)
{ "was" : 0, "slowms" : 100, "ok" : 1 }
      4. Update the document: 
        > db.t.update( {_id:1}, {_id:1, y:1} )
WriteResult({ "nMatched" : 1, "nUpserted" : 0, "nModified" : 1 })
> db.system.profile.find({op:"update"}).pretty()
{
	"op" : "update",
	"ns" : "test2.t",
	"query" : {
		"_id" : 1
	},
	"updateobj" : {
		"_id" : 1,
		"y" : 1
	},
	"nscanned" : 1,
	"nscannedObjects" : -1610612735,
	"nMatched" : 1,
	"nModified" : 1,
	"keyUpdates" : 0,
	"numYield" : 0,
	"lockStats" : {
		"timeLockedMicros" : {
			"r" : NumberLong(0),
			"w" : NumberLong(82)
		},
		"timeAcquiringMicros" : {
			"r" : NumberLong(0),
			"w" : NumberLong(4)
		}
	},
	"millis" : 0,
	"execStats" : {
		
	},
	"ts" : ISODate("2014-09-01T06:06:34.988Z"),
	"client" : "127.0.0.1",
	"allUsers" : [ ],
	"user" : ""
}
      5. Update the document again: 
        > db.t.update( {_id:1}, {_id:1, y:1} )
WriteResult({ "nMatched" : 1, "nUpserted" : 0, "nModified" : 0 })
> db.system.profile.find({op:"update"}).pretty()
......
{
	"op" : "update",
	"ns" : "test2.t",
	"query" : {
		"_id" : 1
	},
	"updateobj" : {
		"_id" : 1,
		"y" : 1
	},
	"nscanned" : 1563717231,
	"nscannedObjects" : 1685091617,
	"nMatched" : 1,
	"nModified" : 0,
	"keyUpdates" : 0,
	"numYield" : 0,
	"lockStats" : {
		"timeLockedMicros" : {
			"r" : NumberLong(0),
			"w" : NumberLong(50)
		},
		"timeAcquiringMicros" : {
			"r" : NumberLong(0),
			"w" : NumberLong(6)
		}
	},
	"millis" : 0,
	"execStats" : {
		
	},
	"ts" : ISODate("2014-09-01T06:06:42.877Z"),
	"client" : "127.0.0.1",
	"allUsers" : [ ],
	"user" : ""
}
      Show
      Start a standalone mongod using 2.6.4 Insert a document: > db.t.insert( { _id :1, x : 1 } ) WriteResult({ "nInserted" : 1 }) Enable profiling: > db.setProfilingLevel(2) { "was" : 0, "slowms" : 100, "ok" : 1 } Update the document: > db.t.update( {_id:1}, {_id:1, y:1} ) WriteResult({ "nMatched" : 1, "nUpserted" : 0, "nModified" : 1 }) > db.system.profile.find({op: "update" }).pretty() { "op" : "update" , "ns" : "test2.t" , "query" : { "_id" : 1 }, "updateobj" : { "_id" : 1, "y" : 1 }, "nscanned" : 1, "nscannedObjects" : -1610612735, "nMatched" : 1, "nModified" : 1, "keyUpdates" : 0, "numYield" : 0, "lockStats" : { "timeLockedMicros" : { "r" : NumberLong(0), "w" : NumberLong(82) }, "timeAcquiringMicros" : { "r" : NumberLong(0), "w" : NumberLong(4) } }, "millis" : 0, "execStats" : { }, "ts" : ISODate( "2014-09-01T06:06:34.988Z" ), "client" : "127.0.0.1" , "allUsers" : [ ], "user" : "" } Update the document again: > db.t.update( {_id:1}, {_id:1, y:1} ) WriteResult({ "nMatched" : 1, "nUpserted" : 0, "nModified" : 0 }) > db.system.profile.find({op: "update" }).pretty() ...... { "op" : "update" , "ns" : "test2.t" , "query" : { "_id" : 1 }, "updateobj" : { "_id" : 1, "y" : 1 }, "nscanned" : 1563717231, "nscannedObjects" : 1685091617, "nMatched" : 1, "nModified" : 0, "keyUpdates" : 0, "numYield" : 0, "lockStats" : { "timeLockedMicros" : { "r" : NumberLong(0), "w" : NumberLong(50) }, "timeAcquiringMicros" : { "r" : NumberLong(0), "w" : NumberLong(6) } }, "millis" : 0, "execStats" : { }, "ts" : ISODate( "2014-09-01T06:06:42.877Z" ), "client" : "127.0.0.1" , "allUsers" : [ ], "user" : "" }

      Issue Status as of Sep 02, 2014

      ISSUE SUMMARY
      In MongoDB 2.6.4, when the profiler is enabled or when a slow query is logged, the number of nscanned and nscannedObjects may be incorrect for update operations when the query part of the update is just a simple equality on the _id field, for example {_id: 4}.

      This issue does not appear when:

      • The update query has predicates over multiple fields: {_id: 1, a: 3}
      • The predicate over _id is not an equality: {_id: {$gt: 3}}
      • The _id equality is for a non-simple type such as a nested object or a JavaScript code type: {_id: {a: "foo"}}

      For example:

      db.t.drop()
db.t.insert( { _id :1, x : 1 } )
db.setProfilingLevel(2)
for (i=0 ; i < 10; i++) {
   db.t.update( {_id:1}, {_id:1, y:i} )
}
db.system.profile.find({op:"update"}, {nscanned: 1, nscannedObjects: 1})
{ "nscanned" : 16802817, "nscannedObjects" : 2053731089 }
{ "nscanned" : 775237691, "nscannedObjects" : 724972601 }
{ "nscanned" : 775237692, "nscannedObjects" : 724972602 }
{ "nscanned" : 31796369, "nscannedObjects" : 2 }
{ "nscanned" : 31796370, "nscannedObjects" : 589827 }
{ "nscanned" : 1, "nscannedObjects" : 805306369 }
{ "nscanned" : 2, "nscannedObjects" : 393218 }
{ "nscanned" : 775237693, "nscannedObjects" : 724972603 }
{ "nscanned" : 3, "nscannedObjects" : 393219 }
{ "nscanned" : 4, "nscannedObjects" : 393220 }

      USER IMPACT
      Users may not be able to get correct information on update operations where the query part of the update is an equality on the _id field.

      WORKAROUNDS
      N/A

      AFFECTED VERSIONS
      MongoDB 2.6.4 is affected by this issue.

      FIX VERSION
      The fix is included in the 2.6.5 production release.

      RESOLUTION DETAILS
      Properly initialize nscanned and nscannedObjects in IDHackRunner.

      Original description

      nscanned and nscannedObjects for update (by _id) are incorrect when profiling is enabled in MongoDB 2.6.4
      The issue is not reproducible in 2.6.3.

            Assignee:
            david.storch@mongodb.com David Storch
            Reporter:
            linda.qin@mongodb.com Linda Qin
            Votes:
            0 Vote for this issue
            Watchers:
            11 Start watching this issue

              Created:
              Updated:
              Resolved: