[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: |
|
||||||||||||||||||||||||||||||||||||
| Assigned Teams: |
Replication
|
||||||||||||||||||||||||||||||||||||
| Backwards Compatibility: | Fully Compatible | ||||||||||||||||||||||||||||||||||||
| Backport Requested: |
v6.0, v5.0, v4.4
|
||||||||||||||||||||||||||||||||||||
| Sprint: | Repl 2023-02-20 | ||||||||||||||||||||||||||||||||||||
| Participants: | |||||||||||||||||||||||||||||||||||||
| Case: | (copied to CRM) | ||||||||||||||||||||||||||||||||||||
| 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: | |
| 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):
| |
| 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 | |
| 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? |