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

Idempotent update by _id usually takes ~5ms but sometimes grow up until ~2500ms

    XMLWordPrintable

Details

    • Question
    • Status: Closed
    • Major - P3
    • Resolution: Done
    • 3.0.15
    • None
    • None
    • None

    Description

      Hello.
      I'm dealing with an update, always over the same collection, that usually takes around 5ms and in certain ocassions it grows up until 2500ms.
      I use the MongoDB 3.0.15 version.
      This is a little part of the log (I attach the log file):

      2018-02-28T16:16:48.219+0100 D REPL     [conn1593794] received notification that node with RID 5a5e7bf033574643f3dbf66a has reached optime: 5a96c7de:5
      2018-02-28T16:16:48.219+0100 D REPL     [conn1593794] Node with RID 5a5e7bf033574643f3dbf66a and memberId 3 currently has optime 5a96c7de:4; updating to 5a96c7de:5
      2018-02-28T16:16:48.219+0100 I COMMAND  [conn1593794] command admin.$cmd command: replSetUpdatePosition { replSetUpdatePosition: 1, optimes: [ { _id: ObjectId('59c650db4399f8e73f242483'), optime: Timestamp 1517423916000|2, memberId: 0, cfgver: 6, config: { _id: 0, host: "gaming01:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 2.0, tags: { client: "B2B01" }, slaveDelay: 0, votes: 1 } }, { _id: ObjectId('59c651496a3fc2ba430fe203'), optime: Timestamp 1519831006000|5, memberId: 1, cfgver: 6, config: { _id: 1, host: "gaming02:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.5, tags: { client: "B2B02" }, slaveDelay: 0, votes: 1 } }, { _id: ObjectId('59c6515d06ee67c2b33c8ce3'), optime: Timestamp 1519831006000|4, memberId: 2, cfgver: 6, config: { _id: 2, host: "gaming03:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: { client: "MURANO" }, slaveDelay: 0, votes: 1 } }, { _id: ObjectId('5a5e7bf033574643f3dbf66a'), optime: Timestamp 1519831006000|5, memberId: 3, cfgver: 6, config: { _id: 3, host: "gaming04:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.3, tags: { client: "B2B04" }, slaveDelay: 0, votes: 1 } } ] } ntoreturn:1 keyUpdates:0 writeConflicts:0 numYields:0 reslen:37 locks:{} 0ms
      2018-02-28T16:16:48.219+0100 I COMMAND  [conn1592412] command b2bgaming.$cmd command: update { update: "user_scores", updates: [ { q: { _id: ObjectId('59d2519ee26b64e4728b4575') }, u: { $set: { hits: 7717 } }, multi: false, upsert: false } ], writeConcern: { j: true, w: 2 } } keyUpdates:0 writeConflicts:0 numYields:0 reslen:95 locks:{ Global: { acquireCount: { r: 3, w: 3 } }, Database: { acquireCount: { w: 3 } }, Collection: { acquireCount: { w: 2 } }, Metadata: { acquireCount: { W: 1 } }, oplog: { acquireCount: { w: 1 } } } 2016ms
      

      Example of normal operation:

      2018-02-28T13:09:04.298+0100 I COMMAND  [conn1579312] command b2bgaming.$cmd command: update { update: "user_scores", updates: [ { q: { _id: ObjectId('59d3a0ade26b648d6c8b4599') }, u: { $set: { hits: 7110 } }, multi: false, upsert: false } ], writeConcern: { j: true, w: 2 } } keyUpdates:0 writeConflicts:0 numYields:0 reslen:95 locks:{ Global: { acquireCount: { r: 3, w: 3 } }, Database: { acquireCount: { w: 3 } }, Collection: { acquireCount: { w: 2 } }, Metadata: { acquireCount: { W: 1 } }, oplog: { acquireCount: { w: 1 } } } 2ms
      

      Thanks!

      Attachments

        Activity

          People

            kelsey.schubert@mongodb.com Kelsey T Schubert
            juanroy Juan Antonio Roy Couto
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: