Log message meaning.

[Venkat]

Hi,

I get the following log message little frequently (1 out of 50
inserts). Is it anything to worry about?

...................
Thu Apr 26 16:05:13 [conn17] comman db.$cmd command: { findAndModify:
"name", fields: { _id: 1 }, upsert: true, query: { name: "larxiu-
secret-de-spuo-to-el-archivo" }, update: { $set: { rank: 0, category:
"sports", name: "larxiu-secret-de-spuo-to-el-archivo" } }, new: true }
ntoreturn:1 keyUpdates:0 reslen:170 305ms
Thu Apr 26 16:05:25 [journal] info journal _rotate called inside
dbMutex - ok but should be somewhat rare
...................

Also I got the 'warning: ClientCursor::yield can't unlock b/c of
recursive lock ns' error even for inserts in an empty db. But after
adding indexes those are gone. Please give me some clarity on this
too.

Thanks.

[Adam C]

> warning: ClientCursor::yield can't unlock b/c of recursive lock ns

When you see that message, it usually indicates that a findAndModify is running on a collection that requires an index but doesn't have a proper one in place, or if the relevant indexes are in place is just a generally inefficient operation.  In general findAndModify operations cannot yield (see here for info on yielding: http://www.mongodb.org/display/DOCS/How+does+concurrency+work#Howdoesconcurrencywork-mongod)

More specifically, the warning indicates that an operation is taking place that has resulted in the mutex being locked multiple times (this is completely intentional as the mutex implementation is recursive – it just needs to be unlocked an equal number of times). The database can only yield at the top-most level of locking; thus, when a yield is requested with multiple layers of locking, the database cannot fulfill the request and will simply continue executing the operation as before. This should not cause concern unless it happens very frequently and results in poor performance (yielding is an optimization to prevent long running operations from monopolizing resources). The most likely cause is a long running operation.

So, this is generally only a warning. There is a Jira issue to improve findAndModify which you can upvote and track at https://jira.mongodb.org/browse/SERVER-1117

Naturally under high load/concurrency this may happen more frequently due to stressing of resources and general slow-down, you should be able to see if that is the case by looking at the usual Memory/IO stats (MMS is great for this) and by seeing if this is more common at your busier times.

I believe the journal message is of similar origin but would need to check to be sure.

Adam