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

slowms should include time spent waiting for writeConcern fulfillment

    • Type: Icon: Improvement Improvement
    • Resolution: Duplicate
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: None
    • Component/s: Replication
    • Labels:
      None

      mongoD slowms logging includes time spent waiting for writeConcern fulfillment. It does not currently split out the time spent executing the write locally vs. time spent waiting for replication when w >= 2. We should provide the write concern wait time separately to allow for easier diagnosis when slow.

      The following is an example of an insert that spent 1000ms waiting for write concern acknowledgement (before timing out).

      2015-12-01T09:22:10.529-0500 d20011| 2015-12-01T09:22:10.529-0500 I COMMAND  [conn1] command test.foo command: insert { insert: "foo", documents: [ { a: 1.0 } ], writeConcern: { w: 3.0, wtimeout: 1000.0 } } ntoreturn:1 ntoskip:0 ninserted:1 keyUpdates:0 writeConflicts:0 numYields:0 reslen:190 locks:{ Global: { acquireCount: { r: 4, w: 4 } }, Database: { acquireCount: { w: 3, W: 1 } }, Collection: { acquireCount: { W: 1 } }, Metadata: { acquireCount: { w: 2 } }, oplog: { acquireCount: { w: 2 } } } protocol:op_command 1041ms
      

            Assignee:
            Unassigned Unassigned
            Reporter:
            james.wahlin@mongodb.com James Wahlin
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Created:
              Updated:
              Resolved: