[SERVER-18067] Add the time spent waiting for write concern in the command log line Created: 15/Apr/15  Updated: 28/Dec/23  Resolved: 16/Feb/23

Status: Closed
Project: Core Server
Component/s: Logging, Write Ops
Affects Version/s: 2.6.9, 3.0.2
Fix Version/s: 7.0.0-rc0

Type: Improvement Priority: Major - P3
Reporter: Alexander Komyagin Assignee: Sean Zimmerman
Resolution: Done Votes: 22
Labels: bkp, former-quick-wins, repl-shortlist
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Backports
Depends
Duplicate
is duplicated by SERVER-21707 slowms should include time spent wait... Closed
Related
related to SERVER-14379 Add Statistics to WriteResult Responses Backlog
related to SERVER-68976 Log time spent waiting for read concern Backlog
related to SERVER-18083 Add serverStatus performance counters... Closed
is related to SERVER-76762 Add time spent waiting for write conc... Closed
Assigned Teams:
Replication
Backwards Compatibility: Fully Compatible
Backport Requested:
v6.0, v5.0, v4.4
Sprint: Repl 2023-02-20
Participants:
Case:

 Description   

When a write command is logged, it should include the time spent waiting for the write concern. It will help in diagnosing issues with write commands being slower than embedded writes



 Comments   
Comment by Githook User [ 16/Feb/23 ]

Author:

{'name': 'seanzimm', 'email': 'sean.zimmerman@mongodb.com', 'username': 'seanzimm'}

Message: SERVER-18067: Add time spent waiting for write concern into command logging
Branch: master
https://github.com/mongodb/mongo/commit/b898508c5cd359aae5ef17505d3861ff0df20f13

Comment by Sean Zimmerman [ 15/Feb/23 ]

Metric will be included in slow query log line for the final wait time and in currentOp output as the current elapsed wait time

Comment by Eric Milkie [ 14/Feb/23 ]

Is this going to add the new metric to both the slow query log line as well as the system.profile document?

Comment by Spencer Brody (Inactive) [ 02/May/18 ]

Yep, happy to take it.

Comment by David Storch [ 30/Apr/18 ]

spencer tess.avitabile, if this is part of a project on the repl team's backlog, should this ticket be moved to the replication backlog?

Comment by Alexander Komyagin [ 15/Apr/15 ]

It's a good option - to add an additional number in the command log line. Here is an example (the additional writeConcernMs field in milliseconds):

2015-04-15T14:01:10.890-0400 I COMMAND  [conn9] command test.$cmd command: insert { insert: "test", documents: [ { _id: ObjectId('552ea765e66fafb1fc24631b'), x: 5.0 } ], ordered: true, writeConcern: { w: 2.0 } } keyUpdates:0 writeConflicts:0 numYields:0 writeConcernMs: XXX reslen:80 locks:{} 1289ms

Comment by Scott Hernandez (Inactive) [ 15/Apr/15 ]

So you want to separate and measure the write concern satisfaction timing separately? This doesn't sound like a new log line, just a new number in the output for the operation.

Can you provide an example of the output you want?

The write and gle were different operations and logged sep.

Comment by Alexander Komyagin [ 15/Apr/15 ]

The intent is to know whether the write command was "slow" because of write concern, or because of something else. In previous versions we had GLE command that would get logged if it takes more than slowms. So it's a logging regression

cc mattd@10gen.com

Comment by Scott Hernandez (Inactive) [ 15/Apr/15 ]

The waiting for the write concern is part of the operation on the server and adheres to the same rules as any other part, since the operation before returning to the client is "slow". Do you have an example of this not happening?

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