[SERVER-20386] Mongo lock stat timeAcquiringMicros way more than query time millis Created: 12/Sep/15  Updated: 05/Nov/15  Resolved: 05/Nov/15

Status: Closed
Project: Core Server
Component/s: Diagnostics, Logging
Affects Version/s: 3.0.4
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: arpit wanchoo Assignee: Ramon Fernandez Marina
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
duplicates SERVER-21305 Lock 'timeAcquiringMicros' value is m... Closed
Operating System: ALL
Participants:

 Description   

Please see below example from my mongo server log. My server was going through high load resulting in slow updates. While debugging the issue I found following in log :

.............update: { $set: { inactive:  { $date : { $numberLong : "1441696817446"} }  } } nscanned:13 nscannedObjects:7 nmoved:1 nMatched:7 nModified:7 keyUpdates:2 writeConflicts:0 numYields:12 locks:{ Global: { acquireCount: { r: 20, w: 20 } }, MMAPV1Journal: { acquireCount: { w: 33 }, acquireWaitCount: { w: 14 }, timeAcquiringMicros: { w: 209519 } }, Database: { acquireCount: { w: 20 } }, Collection: { acquireCount: { W: 13 }, acquireWaitCount: { W: 13 }, timeAcquiringMicros: { W: 43560607112 } }, oplog: { acquireCount: { w: 7 }, acquireWaitCount: { w: 6 }, timeAcquiringMicros: { w: 172644 } } } 392356ms

The timeAcquiringMicros is very large compared to overall query time.
While I was under the impression that millis time includes all the lock times spend during an update operation. Am I correct on this ?



 Comments   
Comment by Ramon Fernandez Marina [ 05/Nov/15 ]

arpit@limeroad.com, this bug has been tracked down and described in detail in SERVER-21305, so I'm going to resolve this ticket. Feel free to watch SERVER-21305 for updates.

Thanks,
Ramón.

Comment by Ramon Fernandez Marina [ 12/Sep/15 ]

Thanks for your report arpit@limeroad.com. If I understand things correctly this issue is being addressed in SERVER-18277. I'll confirm on Monday, and if I'm right I'll be closing this ticket as a duplicate of SERVER-18277.

Regards,
Ramón.

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