[SERVER-15106] Incorrect nscanned and nscannedObjects for idhack updates in 2.6.4 profiler or slow query log Created: 01/Sep/14  Updated: 29/Oct/14  Resolved: 02/Sep/14

Status: Closed
Project: Core Server
Component/s: Write Ops
Affects Version/s: 2.6.4
Fix Version/s: 2.6.5

Type: Bug Priority: Major - P3
Reporter: Linda Qin Assignee: David Storch
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Depends
Related
is related to SERVER-13764 debug mechanisms report incorrect nsc... Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Steps To Reproduce:
  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" : ""
    }

Participants:

 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.



 Comments   
Comment by Githook User [ 02/Sep/14 ]

Author:

{u'username': u'dstorch', u'name': u'David Storch', u'email': u'david.storch@10gen.com'}

Message: SERVER-15106 properly initialize nscanned and nscannedObjects in IDHackRunner
Branch: v2.6
https://github.com/mongodb/mongo/commit/726a75d8decbbdb513bb3e0d860d64f88cdd349a

Comment by David Storch [ 02/Sep/14 ]

This is a bug in the stats reporting of the IDHackRunner which was exposed by the fix in SERVER-13764. The idhack constructor used when there is no CanonicalQuery does not properly initialize nscanned and nscannedObjects to 0. This constructor is only used for idhack updates, which explains the scope of the issue as reported here.

Only the v2.6 branch is affected. In the master branch, the IDHackRunner has been replaced with the IDHackStage. The new IDHackStage does not suffer from this stats reporting issue.

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