ClientCursor::staticYield can't unlock b/c of recursive lock

[Jim Robinson]

Hi folks,

On a mongodb version 2.6.3 running on RHEL5 (kernel 2.6.18-371.1.2.el5):

$ /usr/bin/mongod --version

db version v2.6.3

2015-03-27T09:52:08.242-0700 git version: 255f67a66f9603c59380b2a389e386910bbb52cb

we're seeing a warning logged along the lines of:

2015-03-23T10:54:05.535-0700 [conn5217423] warning: ClientCursor::staticYield can't unlock b/c of recursive lock ns:  top: { opid: 1911578954, active: true, secs_running: 0, microsecs_running: 180, op: "query", ns: "marvin.resource", query: { findAndModify: "resource", query: { _id: "illudium_pu_36" }, update: { $push: { updated.xyz: { m: "xyz", s: 0, c: 46826461, t: 1427133245176295897 } } }, upsert: true, new: true }, client: "10.0.0.3:50085", desc: "conn5217423", threadId: "0x2b03f048c940", connectionId: 5217423, locks: { ^: "w", ^marvin: "W" }, waitingForLock: false, numYields: 0, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: { r: 0, w: 5 } } }

My DBAs and I are looking to see what might be the matter with this,

whether or not there are indexes we need to adjust.

An example of the type of record that might be getting modified:

{

"_id" : "illudium_pu_36",

"deleted" : NumberLong("1371747182531748000"),

"modified" : null,

"updated" : {

"abc" : [

{

"m" : "abc",

"s" : NumberLong(0),

"c" : NumberLong(8),

"t" : NumberLong("1372793818142998603")

},

],

"def" : [

{

"m" : "sor",

"s" : NumberLong(0),

"c" : NumberLong(149),

"t" : NumberLong("1372793784242918479")

}

]

}

}

and an example of the type of findAndModify operation:

db.resource.findAndModify(

{

query: { "_id" : "illudium_pu_36" },

upsert: true,

new: true,

update: {

$push: {

"updated.abc": {

m: "abc",

s: NumberLong(0),

c: NumberLong(148),

t: NumberLong(1372793784242918478)

}

}

}

}

)

The query{} is covered by the default _id index:

db.resource.find( { _id : "illudium_pu_36"} ).explain()

{

"cursor" : "IDCursor",

"n" : 1,

"nscannedObjects" : 1,

"nscanned" : 1,

"indexOnly" : false,

"millis" : 0,

"indexBounds" : {

"_id" : [

[

"illudium_pu_36",

"illudium_pu_36"

]

]

},

"server" : "localhost:27017"

}

I came across this ticket:

https://jira.mongodb.org/browse/SERVER-15583

that makes me think one solution is to update the database, but if

there are changes I can make to the indexes or to the query, I would

like to hear suggestions. For example, should I be creating some

sort of an index against updated.abc to alleviate the issue?

Everything I've read makes me think it is only the query{} I should

be concerned with, but that's automatically indexed so we're unclear

whether or not the $push target needs to be indexed some some fashion

as well.

Thank you,

Jim

[Will Berkeley]

What indexes do you have on the collection? How large are the "xyz" arrays that you are pushing into, usually?

-Will

--
You received this message because you are subscribed to the Google Groups "mongodb-user"
group.
 
For other MongoDB technical support options, see: http://www.mongodb.org/about/support/.
---
You received this message because you are subscribed to the Google Groups "mongodb-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to mongodb-user...@googlegroups.com.
To post to this group, send email to mongod...@googlegroups.com.
Visit this group at http://groups.google.com/group/mongodb-user.
To view this discussion on the web visit https://groups.google.com/d/msgid/mongodb-user/90d83c32-ad27-4934-b4c1-5555b76b3aad%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[James A. Robinson]

On Fri, Mar 27, 2015 at 12:06 PM, Will Berkeley <william....@mongodb.com> wrote:

What indexes do you have on the collection? How large are the "xyz" arrays that you are pushing into, usually?

Hi,

Thank you for the reply.

The size of the xyz arrays will typically be between 0 and 10.  It

depends on how often someone wants to change the document during

the day.  We have a daily process that prunes the array back down

to 1.

There  are two general purpose indexes and a number of "xyz"

indexes.  The two general purposes ones are:

{

"v" : 1,

"key" : {

"_id" : 1

},

"ns" : "marvin.resource",

"name" : "_id_"

},

{

"v" : 1,

"key" : {

"ancestors" : 1,

"type" : 1,

"role" : 1,

"lang" : 1

},

"ns" : "marvin.resource",

"name" : "ancestors_1_type_1_role_1_lang_1",

"background" : true

},

And the "xyz" specific ones look like:

{

"v" : 1,

"key" : {

"updated.xyz.s" : 1

},

"ns" : "marvin.resource",

"name" : "updated.xyz.s_1",

"sparse" : true

},

{

"v" : 1,

"key" : {

"released.xyz.s" : 1

},

"ns" : "marvin.resource",

"name" : "released.xyz.s_1",

"sparse" : true

},

{

"v" : 1,

"key" : {

"embargoed.xyz.s" : 1

},

"ns" : "marvin.resource",

"name" : "embargoed.xyz.s_1",

"sparse" : true

},

Not all the "xyz" style subdocuments have the indexes, but we're

seeing the warning on both subdocuments that do have these

indexes and that do not have them.

The total size of the indexes for that particular collection is

24.2248 gigabytes, the machine is configured for 32 gigabytes of

memory, I'm not sure what limit, if any, is being set on mongodb.

mongodb is currently using 26 gigabytes of memory according

to top(1), I'm not sure how much of that is devoted to indexes

vs. other overhead requirements.

The db.resource.stats() shows the following:

{

"ns" : "marvin.resource",

"count" : 24682070,

"size" : 41562652624,

"avgObjSize" : 1683,

"storageSize" : 52233957040,

"numExtents" : 45,

"nindexes" : 11,

"lastExtentSize" : 2146426864,

"paddingFactor" : 1.941000000000012,

"systemFlags" : 1,

"userFlags" : 0,

"totalIndexSize" : 24225038320,

"indexSizes" : {

"_id_" : 2065609168,

"ancestors_1_type_1_role_1_lang_1" : 22070883072,

"updated.xyz.s_1" : 41632192,

"released.xyz.s_1" : 8176,

"embargoed.xyz.s_1" : 8176,

"updated.abc.s_1" : 16965200,

"released.abc.s_1" : 15248240,

"embargoed.abc.s_1" : 14659568,

"updated.def.s_1" : 8176,

"released.def.s_1" : 8176,

"embargoed.def.s_1" : 8176

},

"ok" : 1

}

The size of all the indexes combined is 24.26 gigabytes:

atomlog:

"_id_" : 8176

monitor:

"_id_" : 8176

resource:

"_id_" : 2065609168,

"ancestors_1_type_1_role_1_lang_1" : 22070883072,

"updated.xyz.s_1" : 41632192,

"released.xyz.s_1" : 8176,

"embargoed.xyz.s_1" : 8176,

"updated.abc.s_1" : 16965200,

"released.abc.s_1" : 15248240,

"embargoed.abc.s_1" : 14659568,

"updated.def.s_1" : 8176,

"released.def.s_1" : 8176,

"embargoed.def.s_1" : 8176

sequence:

"_id_" : 8176

status:

"_id_" : 24528

transaction:

"_id_" : 21102256,

"created_1" : 14700448

[James A. Robinson]

Anyone else have any thoughts on this error? I'm trying to nail
down whether the problem is due to (a) insufficient memory,
(b) indexes, (c) a bug that requires a mongodb upgrade.

I'd rather not shoot blind and start changing things w/o some
better idea of the source of the underlying problem.

Jim