[SERVER-12595] findandmodify not honoring maxTimeMS Created: 04/Feb/14  Updated: 11/Jul/16  Resolved: 05/Feb/14

Status: Closed
Project: Core Server
Component/s: Concurrency
Affects Version/s: 2.5.5
Fix Version/s: 2.6.0-rc0

Type: Bug Priority: Major - P3
Reporter: Robert Moore Assignee: Eric Milkie
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Linux XXX 3.12.8-300.fc20.x86_64 #1 SMP Thu Jan 16 01:07:50 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux

$ ./mongod --version
db version v2.5.5
2014-02-03T19:51:00.678-0500 git version: 5f2ad3f6411cb1c727e4b836798b8ef06de25f2d
$ ./mongo --version
MongoDB shell version: 2.5.5


Issue Links:
Duplicate
is duplicated by SERVER-12780 findAndModify doesn't honour MaxTimeMS Closed
Backwards Compatibility: Fully Compatible
Operating System: Linux
Steps To Reproduce:

See description.

Participants:

 Description   

The findandmodify command the group commands are not honoring the maxTimeMS option.

Here is an example using the findandmodify command:

$ ./mongo
MongoDB shell version: 2.5.5
connecting to: test
Server has startup warnings: 
2014-02-03T19:24:05.729-0500 [initandlisten] 
2014-02-03T19:24:05.729-0500 [initandlisten] ** NOTE: This is a development version (2.5.5) of MongoDB.
2014-02-03T19:24:05.729-0500 [initandlisten] **       Not recommended for production.
2014-02-03T19:24:05.729-0500 [initandlisten] 
> for (var i = 1; i <= 1000000; i++) db.testData.insert( { x : i } )
SingleWriteResult({
	"writeErrors" : [ ],
	"writeConcernErrors" : [ ],
	"nInserted" : 1,
	"nUpserted" : 0,
	"nUpdated" : 0,
	"nModified" : 0,
	"nRemoved" : 0,
	"upserted" : [ ]
})
> db.testData.stats()
{
	"ns" : "test.testData",
	"count" : 1000000,
	"size" : 48000144,
	"avgObjSize" : 48,
	"storageSize" : 86310912,
	"numExtents" : 10,
	"nindexes" : 1,
	"lastExtentSize" : 27869184,
	"paddingFactor" : 1,
	"systemFlags" : 1,
	"userFlags" : 1,
	"totalIndexSize" : 32458720,
	"indexSizes" : {
		"_id_" : 32458720
	},
	"ok" : 1
}
> db.runCommand( { "findandmodify" : "testData", "query" : { "z" : 1 }, "update" : { "$inc" : { "x" : 1 } }, "maxTimeMS" : 1 } )
{ "value" : null, "ok" : 1 }
> db.runCommand( { "findandmodify" : "testData", "query" : { "z" : 1 }, "update" : { "$inc" : { "x" : 1 } }, "maxTimeMS" : 10 } )
{ "value" : null, "ok" : 1 }
> db.runCommand( { "findandmodify" : "testData", "query" : { "z" : 1 }, "update" : { "$inc" : { "x" : 1 } }, "maxTimeMS" : 100 } )
{ "value" : null, "ok" : 1 }

In the server logs I see:

2014-02-03T19:53:34.262-0500 [conn1] command test.$cmd command: { findandmodify: "testData", query: { z: 1.0 }, update: { $inc: { x: 1.0 } }, maxTimeMS: 1.0 } keyUpdates:0 numYields:0 locks(micros) w:219550 reslen:44 219ms
2014-02-03T19:53:38.555-0500 [conn1] command test.$cmd command: { findandmodify: "testData", query: { z: 1.0 }, update: { $inc: { x: 1.0 } }, maxTimeMS: 10.0 } keyUpdates:0 numYields:0 locks(micros) w:195078 reslen:44 195ms
2014-02-03T19:53:43.077-0500 [conn1] command test.$cmd command: { findandmodify: "testData", query: { z: 1.0 }, update: { $inc: { x: 1.0 } }, maxTimeMS: 100.0 } keyUpdates:0 numYields:0 locks(micros) w:213143 reslen:44 213ms

Similar for the group command:

> db.runCommand( { group: { key: "z", $reduce: function ( curr, result ) { }, initial: {}, maxTimeMS: 100.0, ns: "testData" } } )
{ "retval" : [ { } ], "count" : 1000000, "keys" : 1, "ok" : 1 }

and in the log:

2014-02-03T20:03:21.412-0500 [conn1] command test.$cmd command: { group: { key: "z", $reduce: function ( curr, result ) { }, initial: {}, maxTimeMS: 100.0, ns: "testData" } } keyUpdates:0 numYields:0 locks(micros) r:6083207 reslen:83 6083ms

Note: I am only manually creating the commands so I can inspect the full results.



 Comments   
Comment by Robert Moore [ 06/Feb/14 ]

Eric -

Good too see the fix for findAndModify go in.

As requested I created ticket SERVER-12636 for the text command issue.

Rob.

Comment by Githook User [ 05/Feb/14 ]

Author:

{u'username': u'milkie', u'name': u'Eric Milkie', u'email': u'milkie@10gen.com'}

Message: SERVER-12595 findAndModify should yield in the same manner as update
Branch: master
https://github.com/mongodb/mongo/commit/b270a715d8239d54bc52e29bac0ef970fa29f99e

Comment by Eric Milkie [ 05/Feb/14 ]

I've modifed the subject a bit now. Can you make a separate ticket for the 'text' command? It may need a different fix to get working.

Comment by Robert Moore [ 05/Feb/14 ]

I was able to duplicate the group timeout by moving it out of the'group' sub document.

For the text command I don't see a helper function in the docs. The runCommand I used was modified from the examples here: http://docs.mongodb.org/manual/reference/command/text/.

I also tried this format for the text command with the same result.

> db.runCommand( { "text" : "testData", search : "good" , maxTimeMS : 100 } )
{
	"results" : [
            // Removed.
	],
	"stats" : {
		"nscanned" : NumberLong(100000),
		"nscannedObjects" : NumberLong(100000),
		"n" : 100,
		"timeMicros" : 135148
	},
	"ok" : 1
}

Rob.

Comment by Eric Milkie [ 04/Feb/14 ]

I believe the same is true for the 'text' command. I would try making maxTimeMS a parameter to the runCommand shell helper function.
Incidentally, don't you need a colon instead of a comma after "text"?

Comment by Eric Milkie [ 04/Feb/14 ]

For the "group" command, if you pass the maxTimeMS parameter as a parameter to the runCommand function rather than as a parameter to the group command (i.e. the same way you are passing it for other commands such as findAndModify), it will work, although the error message just shows it was interrupted and doesn't specify that it was due to the maximum time limit being reached:

 db.runCommand( { group: { key: "z", $reduce: function ( curr, result ) { }, initial: {}, ns: "testData" }, maxTimeMS : 200 } )
{
	"errmsg" : "exception: JavaScript execution terminated",
	"code" : 16711,
	"ok" : 0
}

Comment by Eric Milkie [ 04/Feb/14 ]

I added a yield policy to Helpers::findOne() and this alleviates the issue, at least with findAndModify. I need to check with some other engineers to see if this solution is viable.

Comment by Eric Milkie [ 04/Feb/14 ]

I did some initial testing of findAndModify. The first thing it does (when your query does not have a 'sort') is do a findOne() to get the document. That helper just uses a simple Runner to find the document, and in my testing it's not yielding in the ~100ms or so that it takes to scan the collection. I'm going to play around with this a bit more.

Comment by Robert Moore [ 04/Feb/14 ]

Just discovered that the 'text' command is also ignoring the timeout.

> db.testData.drop()
true
> for (var i = 1; i <= 100000; i++) db.testData.insert( { x : i, "text" : "Now is the time for all good men to come to the aid of..." } )
SingleWriteResult({
	"writeErrors" : [ ],
	"writeConcernErrors" : [ ],
	"nInserted" : 1,
	"nUpserted" : 0,
	"nUpdated" : 0,
	"nModified" : 0,
	"nRemoved" : 0,
	"upserted" : [ ]
})> db.testData.stats()
{
	"ns" : "test.testData",
	"count" : 100000,
	"size" : 11200000,
	"avgObjSize" : 112,
	"storageSize" : 22507520,
	"numExtents" : 7,
	"nindexes" : 2,
	"lastExtentSize" : 11325440,
	"paddingFactor" : 1,
	"systemFlags" : 1,
	"userFlags" : 1,
	"totalIndexSize" : 21723632,
	"indexSizes" : {
		"_id_" : 3262224,
		"text_text" : 18461408
	},
	"ok" : 1
}
> db.testData.runCommand( "text" , { search : "good" , maxTimeMS : 100 } )
{
	"results" : [
<snip/>
	],
	"stats" : {
		"nscanned" : NumberLong(100000),
		"nscannedObjects" : NumberLong(100000),
		"n" : 100,
		"timeMicros" : 145226
	},
	"ok" : 1
}

And again in the server log we see that the command is over the 100 ms limit:

2014-02-03T20:12:03.770-0500 [conn1] command test.$cmd command: { text: "testData", search: "good", maxTimeMS: 100.0 } keyUpdates:0 numYields:0 locks(micros) r:148545 reslen:13119 148ms

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