Why mongo taks 15 seconds to update a record?

[TJ Tang]

I'm reviewing the mongo profiling data and noticed that there is one update job took nearly 15 seconds. The code was trying to update some user data in the User collection which has about 120K entries. 

Here's the profile output:

{

"ts" : ISODate("2013-05-24T12:59:44.610Z"),

"op" : "update",

"ns" : "gf2.User",

"query" : {

"_id" : "gfu-iqckom"

},

"updateobj" : {

"$set" : {

"random" : [

0.040397967884538866,

0.9845285429580969

],

"games" : [

{

"name" : "xxxxxx.com",

"trophies" : [

{

"date" : 1369322506.962343,

"id" : "welcome"

},

{

"date" : 1369323539.185573,

"id" : "fb_connect"

}

]

},

{

"timestamp" : 1369400360,

"data" : {

"create_tm" : 1369400360.618168

},

"name" : "xxxxxx"

}

],

"update_tm" : 1369400360.618263

}

},

"nscanned" : 1,

"moved" : true,

"nmoved" : 1,

"nupdated" : 1,

"keyUpdates" : 0,

"numYield" : 0,

"lockStats" : {

"timeLockedMicros" : {

"r" : NumberLong(0),

"w" : NumberLong(14833109)

},

"timeAcquiringMicros" : {

"r" : NumberLong(0),

"w" : NumberLong(2985)

}

},

"millis" : 14833,

"client" : "10.0.0.12",

"user" : ""

}

And the stats for the relevant collection:

rssh1:PRIMARY> db.User.stats()

{

"ns" : "gf2.User",

"count" : 125872,

"size" : 1421237056,

"avgObjSize" : 11291.129528409812,

"storageSize" : 9082679280,

"numExtents" : 23,

"nindexes" : 7,

"lastExtentSize" : 2146426864,

"paddingFactor" : 1.020000001594492,

"systemFlags" : 0,

"userFlags" : 0,

"totalIndexSize" : 2016168896,

"indexSizes" : {

"_id_" : 5338928,

"user_id_1" : 5486096,

"fbID_1" : 5052768,

"email_1" : 7113120,

"tags.facebook_friends_1" : 1980783168,

"games.name" : 11307408,

"random" : 1087408

},

"ok" : 1

}

This mongod is the primary of the 2 nodes replica set(including one arbiter node). The secondary is currently in the resync process. The client code is using pymongo and the write concern level is only on the Primary, i.e., it should return without having to wait for the data to be replicated. 

 What could be the possible reasons a write could take up so much time?  

[Tyler Brock]

It had to be moved to the end of the collection because the document increased in size.

This operation requires the current document be removed and added to the freelist, the current document be removed in the index, the new document written to the database, the new document be added to the index.

I'm assuming the query is indexed because you are using the '_id' field but that could be a potential issue as well.

-Tyler

[TJ Tang]

Thanks for the quick response. It makes sense. So is it normal for Mongo to spend 15 seconds for such an operation? Seems this would be somewhat frequent operations. 15 seconds seemed to be a bit long.

Yes the _id is indexed.

[Asya Kamsky]

It's not "normal" but it's certainly normal that operations that have to relocated a document are going to be much slower than operations that can update a document in place.

This is why we advise to have schema that does not continuously grow documents without bounds.  That's also why MongoDB itself will start padding (i.e. allocating more space) for each document as it detects that it needed to be moved to perform an update.

If you run this sort of update all the time but this is one of very few that took this long it's also possible that something else was going on on the system at that time and normally this operation might not take nearly as long.

Asya