Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-20386

Mongo lock stat timeAcquiringMicros way more than query time millis

    • Type: Icon: Bug Bug
    • Resolution: Duplicate
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: 3.0.4
    • Component/s: Diagnostics, Logging
    • Labels:
      None
    • ALL

      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 ?

            Assignee:
            ramon.fernandez@mongodb.com Ramon Fernandez Marina
            Reporter:
            arpit@limeroad.com arpit wanchoo
            Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

              Created:
              Updated:
              Resolved: