[SERVER-15583] warning: ClientCursor::staticYield can't unlock b/c of recursive lock Created: 09/Oct/14  Updated: 19/Jul/15  Resolved: 09/Jun/15

Status: Closed
Project: Core Server
Component/s: Querying
Affects Version/s: 2.6.4
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Luca casali Assignee: Unassigned
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
duplicates SERVER-18620 Reduce frequency of "staticYield can'... Closed
Related
Backwards Compatibility: Fully Compatible
Operating System: ALL
Steps To Reproduce:

Fill a collection with lots of records. Create at least 3 indexes and try to do a find a modify repeatedly (high frequence) that is covered completly by only one index of the 3 you've created.

Participants:

 Description   

After migrating 2.6 node in our replicaset it starts filling logs files up at an extraordinary rate. I get many "warning: ClientCursor::staticYield can't unlock b/c of recursive" log messages every few milliseconds.

The problem it seems related to the query plan executor. Sometimes it does not use the right index and obviously it take to much time.

This problem is filling up our logs.



 Comments   
Comment by Leif Mortenson [ 16/Jul/15 ]

We are also having this problem. I read the recommendation to use hint. But how do you do that with a findAndModify query?
I tried:
db.timePeriods.findAndModify( {query: { "$query":

{ t: ObjectId('51e73c5f84aeafda6bc1749d'), bt: 1500000000 }

, "$hint":

{ t: 1, bt: -1 }

}, update: {$set: {xyz:1}} } );

But this results in:
2015-07-16T10:50:16.088+0900 findAndModifyFailed failed: {
"errmsg" : "exception: Could not canonicalize { $query:

{ t: ObjectId('51e73c5f84aeafda6bc1749d'), bt: 1500000000.0 }

, $hint:

{ t: 1.0, bt: -1.0 }

}",
"code" : 17383,
"ok" : 0
} at src/mongo/shell/collection.js:614

Of course a standard find works correctly:
db.timePeriods.find( { "$query":

{ t: ObjectId('51e73c5f84aeafda6bc1749d'), bt: 1500000000 }

, "$hint":

{ t: 1, bt: -1 }

} );

We are running 2.6.10.

Thanks in advance

Comment by Daniel Pasette (Inactive) [ 08/Jun/15 ]

tuerkben@adobe.com, please go ahead and create a new commercial support ticket for this issue.

Comment by Ilyas Türkben [ 08/Jun/15 ]

We are also having similar warnings like the following in MongoDB 2.6.7:

{  
   opid:114291,
   active:true,
   secs_running:0,
   microsecs_running:13296,
   op:"query",
   ns:"aem.nodes",
   query:{  
      findandmodify:"nodes",
      query:{  
         _id:"12:/oak:index/cqLastModified/:index/2015-04-14T16:19:57.408+02:00/content/www/FULL_PATH_REMOVED"
      },
      update:{  
         $set:{  
            _deletedOnce:true,
            _deleted.r14daf07100e-0-6:"true",
            match.r14daf07100e-0-6:null,
            _commitRoot.r14daf07100e-0-6:"0"
         },
         $max:{  
            _modified:1433160585
         },
         $inc:{  
            _modCount:1
         }
      },
      upsert:true
   },
   client:"192.168.194.24:50561",
   desc:"conn294",
   threadId:"0x7f772a3f0700",
   connectionId:294,
   locks:{  
      ^:"w",
      ^aem:"W"
   },
   waitingForLock:false,
   numYields:0,
   lockStats:{  
      timeLockedMicros:{  
 
      },
      timeAcquiringMicros:{  
         r:0,
         w:1
      }
   }
}

This is an AEM instance. Should we open a new JIRA issue ?

Comment by Manan Shah [ 29/May/15 ]

Thank you. Tried a bunch of combination of different indexes including the one you suggested. The actual index that the plan is honoring is only when there's a index on

{"r.w" : 1}

. No hint is required for this. When added the index for

{s:1, r.w:1}

and tried to impose it with the hint the query plan turned bad plus it never resolved the original problem
This is how the plan is for that query in the log now (which looks good but logging for those warnings hasn't stopped)

PRIMARY> db.expirationwork.find({ $and: [ { s: 0 }, { $or: [ { "r.w": { $exists: false } }, { "r.w": 60 } ] }, { "r.b": { $ne: 60 } } ] }).sort({ p : 1}).explain()
{
        "cursor" : "BtreeCursor r.w_1",
        "isMultiKey" : true,
        "n" : 0,
        "nscannedObjects" : 1,
        "nscanned" : 2,
        "nscannedObjectsAllPlans" : 1,
        "nscannedAllPlans" : 2,
        "scanAndOrder" : true,
        "indexOnly" : false,
        "nYields" : 0,
        "nChunkSkips" : 0,
        "millis" : 0,
        "indexBounds" : {
                "r.w" : [
                        [
                                null,
                                null
                        ],
                        [
                                60,
                                60
                        ]
                ]
        },
        "server" : "xxx-mongo6:27056",
        "filterSet" : false
}

This is the plan when I tried to impose the composite index with the hint:

PRIMARY> db.expirationwork.find({ $and: [ { s: 0 }, { $or: [ { "r.w": { $exists: false } }, { "r.w": 60 } ] }, { "r.b": { $ne: 60 } } ] }).sort({ p : 1}).hint({"s" : 1,"r.w" : 1}).explain()
{
        "cursor" : "BtreeCursor s_1_r.w_1",
        "isMultiKey" : true,
        "n" : 1,
        "nscannedObjects" : 317212,
        "nscanned" : 958844,
        "nscannedObjectsAllPlans" : 317212,
        "nscannedAllPlans" : 958844,
        "scanAndOrder" : true,
        "indexOnly" : false,
        "nYields" : 7491,
        "nChunkSkips" : 0,
        "millis" : 23827,
        "indexBounds" : {
                "s" : [
                        [
                                0,
                                0
                        ]
                ],
                "r.w" : [
                        [
                                {
                                        "$minElement" : 1
                                },
                                {
                                        "$maxElement" : 1
                                }
                        ]
                ]
        },
        "server" : "xxx-mongo6:27056",
        "filterSet" : false
}
 
PRIMARY> db.version()
2.6.8

Note that at this point the MongoDB version has also been upgraded to 2.6.8 from the previous 2.6.3 when we first encountered this issue.
Should I create a separate JIRA ticket? Any suggestions would be greatly appreciated as the logs for this instance alone are filling up the disk space at roughly 5G / hour.

Comment by Ramon Fernandez Marina [ 28/May/15 ]

manan@indeed.com, if 2.6.8 doesn't fix your issue then you're running into a different problem.

My guess is that you're running into SERVER-15225. Please see this comment in SERVER-17054 for a detailed explanation of a scenario that can trigger this issue.

The suggested workaround is to use a hint(); in your case you may want to try with indexes {s:1} and {s:1, r.w:1} for example. If this doesn't help please open a separate ticket and provide details about your indexes and full mongod logs when experiencing the slow queries.

Thanks,
Ramón.

Comment by Manan Shah [ 27/May/15 ]

Hello
We're facing similar issue and neither adding the index nor upgrading from 2.6.3 to 2.6.8 seem to fixed the problem. The error is of the following type:

2015-05-27T18:18:50.192-0500 [conn35] warning: ClientCursor::staticYield can't unlock b/c of recursive lock ns:  top: { opid: 14571, active: true, secs_running: 0, microsecs_running: 823961, op: "query", ns: "henson_qa", query: { findandmodify: "expirationwork", query: { $and: [ { s: 0 }, { $or: [ { r.w: { $exists: false } }, { r.w: 58 } ] }, { r.b: { $ne: 58 } } ] }, sort: { p: 1 }, update: { $set: { s: 1, lut: 1432768729365 } }, new: true }, client: "10.x.x.x:58980", desc: "conn35", threadId: "0x7f4326c63700", connectionId: 35, locks: { ^: "w", ^henson_qa: "W" }, waitingForLock: false, numYields: 0, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: { r: 0, w: 6 } } }
2015-05-27T18:18:50.193-0500 [conn35] warning: ClientCursor::staticYield can't unlock b/c of recursive lock ns:  top: { opid: 14571, active: true, secs_running: 0, microsecs_running: 824538, op: "query", ns: "henson_qa", query: { findandmodify: "expirationwork", query: { $and: [ { s: 0 }, { $or: [ { r.w: { $exists: false } }, { r.w: 58 } ] }, { r.b: { $ne: 58 } } ] }, sort: { p: 1 }, update: { $set: { s: 1, lut: 1432768729365 } }, new: true }, client: "10.x.x.x:58980", desc: "conn35", threadId: "0x7f4326c63700", connectionId: 35, locks: { ^: "w", ^henson_qa: "W" }, waitingForLock: false, numYields: 0, lockStats: { timeLockedMicros: {}, timeAcquiringMicros: { r: 0, w: 6 } } }

Please suggest a fix.
Thank you.

Comment by Ramon Fernandez Marina [ 12/Dec/14 ]

Thanks for letting us know lucacasali. Glad to hear that 2.6.6 fixed the problem.

Comment by Luca casali [ 11/Dec/14 ]

Sorry for the late answer we got a very busy time. Issue we had has been solved by 2.6.6 se installed yestarday.

Comment by J Rassi [ 04/Dec/14 ]

A sidenote: work is being done in SERVER-15715 to remove the usage of DBDirectClient from findAndModify, which has the consequence of permitting all findAndModify operations to yield.

Comment by Ramon Fernandez Marina [ 04/Dec/14 ]

lucacasali, we haven't heard back from you for some time. Is this still an issue for you? If so, can you please provide the information requested above? Note also that a 2.6.6-rc0 release candidate was published earlier this week with more improvements in this area, so it might be worth trying to test this version as well.

Thanks,
Ramón.

Comment by Daniel Pasette (Inactive) [ 10/Oct/14 ]

Hi Luca,
As you suspected, this message is often printed when the query used by the findAndModify is unindexed or using an inefficient index. Can you include the explain() output for the quey? Take the part from the findAndModify log like inside "query" and run
it in the shell with explain and also include the indexes you have for the collection:

> db.collection.find({query-here}).explain();
> db.collection.getIndexes();

If you have a test environment which is showing this behavior, could you also try this query with 2.6.5 which just came out? There are a number of query optimizer fixes in this release.

Comment by Luca casali [ 09/Oct/14 ]

All the logs we have contain find and modify query.

Comment by Luca casali [ 09/Oct/14 ]

I missed an import details it appends only with findandmodify query

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