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

Mongo lock stat timeAcquiringMicros way more than query time millis

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major - P3
    • Resolution: Duplicate
    • Affects Version/s: 3.0.4
    • Fix Version/s: None
    • Component/s: Diagnostics, Logging
    • Labels:
      None
    • Operating System:
      ALL

      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 ?

        Attachments

          Issue Links

            Activity

              People

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

                Dates

                Created:
                Updated:
                Resolved: