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

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major - P3
    • Resolution: Fixed
    • Affects Version/s: 2.6.4
    • Fix Version/s: 2.6.5
    • Component/s: Write Ops
    • Labels:
      None
    • Backwards Compatibility:
      Fully Compatible
    • Operating System:
      ALL
    • Steps To Reproduce:
      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" : "" }

      Description

      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.

        Attachments

          Issue Links

            Activity

              People

              • Votes:
                0 Vote for this issue
                Watchers:
                12 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: