-
Type:
Improvement
-
Resolution: Done
-
Priority:
Major - P3
-
None
-
Affects Version/s: 2.4.0-rc0
-
Component/s: Concurrency
-
None
-
Fully Compatible
It appears that we are yielding quite a bit in receivedQuery and receivedGetMore when a secondary is pulling from the oplog. In the scenario shown below the secondary was catching up. The output below is from when it was scanning before reaching a { ts :
{ $gte : ... }} point; after that it is yielding except maybe every 3ms instead of every 1ms.
This test was done on windows.
An extra 1K local db lock acquisitions per second can't be helpful...
Thu Feb 21 14:01:01.264 [conn1] yield haveReadLock:1 micros:-1 rec:0000000000000000 Thu Feb 21 14:01:01.265 [conn1] yield haveReadLock:1 micros:-1 rec:0000000000000000 Thu Feb 21 14:01:01.266 [conn1] yield haveReadLock:1 micros:-1 rec:0000000000000000 Thu Feb 21 14:01:01.267 [conn1] yield haveReadLock:1 micros:-1 rec:0000000000000000 Thu Feb 21 14:01:01.268 [conn1] yield haveReadLock:1 micros:-1 rec:0000000000000000 Thu Feb 21 14:01:01.269 [conn1] yield haveReadLock:1 micros:-1 rec:0000000000000000 Thu Feb 21 14:01:01.270 [conn1] yield haveReadLock:1 micros:-1 rec:0000000000000000 Thu Feb 21 14:01:01.271 [conn1] yield haveReadLock:1 micros:-1 rec:0000000000000000 Thu Feb 21 14:01:01.272 [conn1] yield haveReadLock:1 micros:-1 rec:0000000000000000 Thu Feb 21 14:01:01.273 [conn1] yield haveReadLock:1 micros:-1 rec:0000000000000000 Thu Feb 21 14:01:01.274 [conn1] yield haveReadLock:1 micros:-1 rec:0000000000000000 Thu Feb 21 14:01:01.275 [conn1] yield haveReadLock:1 micros:-1 rec:0000000000000000 Thu Feb 21 14:01:01.276 [conn1] yield haveReadLock:1 micros:-1 rec:0000000000000000 Thu Feb 21 14:01:01.277 [conn1] yield haveReadLock:1 micros:-1 rec:0000000000000000 Thu Feb 21 14:01:01.278 [conn1] yield haveReadLock:1 micros:-1 rec:0000000000000000 Thu Feb 21 14:01:01.279 [conn1] yield haveReadLock:1 micros:-1 rec:0000000000000000 Thu Feb 21 14:01:01.280 [conn1] yield haveReadLock:1 micros:-1 rec:0000000000000000 Thu Feb 21 14:01:01.281 [conn1] yield haveReadLock:1 micros:-1 rec:0000000000000000 Thu Feb 21 14:01:01.282 [conn1] yield haveReadLock:1 micros:-1 rec:0000000000000000 Thu Feb 21 14:01:01.283 [conn1] yield haveReadLock:1 micros:-1 rec:0000000000000000 Thu Feb 21 14:01:01.284 [conn1] yield haveReadLock:1 micros:-1 rec:0000000000000000 Thu Feb 21 14:01:01.285 [conn1] yield haveReadLock:1 micros:-1 rec:0000000000000000 Thu Feb 21 14:01:01.286 [conn1] yield haveReadLock:1 micros:-1 rec:0000000000000000 Thu Feb 21 14:01:01.287 [conn1] yield haveReadLock:1 micros:-1 rec:0000000000000000 Thu Feb 21 14:01:01.288 [conn1] yield haveReadLock:1 micros:-1 rec:0000000000000000 Thu Feb 21 14:01:01.289 [conn1] yield haveReadLock:1 micros:-1 rec:0000000000000000
More info:
- ElapsedTracker::intervalHasElapsed: _hitsBetweenMarks == 256 during initial scan, 128 later when returning documents.
- server was otherwise idle, so no one was queued and waiting for a lock
- here is some profiler output. note that while this # is high, exclusive millis was sometimes quite low as getmore is very fast compared to the secondary applying the ops.
initial scan:
queryWithQueryOptimizer() 100%
FindingStartCurosr::next() 89%
staticYield 8%
getmore:
receivedGetMore() 97%
ClientCursor::yieldSometimes() 33%
- related to
-
SERVER-8579 Consolidate Mongod Lock/Resource Scheduling Logic
-
- Closed
-