[SERVER-32146] Log slow oplog entry application Created: 01/Dec/17 Updated: 30/Oct/23 Resolved: 25/Oct/18 |
|
| Status: | Closed |
| Project: | Core Server |
| Component/s: | Diagnostics, Replication |
| Affects Version/s: | None |
| Fix Version/s: | 3.6.11, 4.0.6, 4.1.5 |
| Type: | Improvement | Priority: | Major - P3 |
| Reporter: | Judah Schvimer | Assignee: | Vesselina Ratcheva (Inactive) |
| Resolution: | Fixed | Votes: | 2 |
| Labels: | SWDI, neweng | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Attachments: |
|
||||||||||||||||||||||||||||||||
| Issue Links: |
|
||||||||||||||||||||||||||||||||
| Backwards Compatibility: | Fully Compatible | ||||||||||||||||||||||||||||||||
| Backport Requested: |
v4.0, v3.6
|
||||||||||||||||||||||||||||||||
| Sprint: | Repl 2018-10-08, Repl 2018-10-22, Repl 2018-11-05 | ||||||||||||||||||||||||||||||||
| Participants: | |||||||||||||||||||||||||||||||||
| Description |
|
We log slow operations on the primary, it would also be helpful to log slow oplog application to see what's using system resources. |
| Comments |
| Comment by Githook User [ 24/Jan/19 ] |
|
Author: {'username': 'vessy-mongodb', 'email': 'vesselina.ratcheva@10gen.com', 'name': 'Vesselina Ratcheva'}Message: (cherry picked from commit 66434ba0a7930efedbe5e06a098ab8e7bb659cfa) |
| Comment by Githook User [ 11/Jan/19 ] |
|
Author: {'username': 'vessy-mongodb', 'email': 'vesselina.ratcheva@10gen.com', 'name': 'Vesselina Ratcheva'}Message: (cherry picked from commit 66434ba0a7930efedbe5e06a098ab8e7bb659cfa) |
| Comment by Githook User [ 25/Oct/18 ] |
|
Author: {'name': 'Vesselina Ratcheva', 'email': 'vesselina.ratcheva@10gen.com', 'username': 'vessy-mongodb'}Message: |
| Comment by Vesselina Ratcheva (Inactive) [ 24/Oct/18 ] |
|
In a different discussion, we considered whether we should support logging all oplog application (not just slow operations) at log level 1, similar to how slow commands are logged. We decided against this, as we have no real use for logging for non-slow operations on secondaries, especially given that the primary already has the ability to log that generously on its own end. Instead, we're more concerned with keeping the logs cleaner and minimizing the perf impact, so we're only going to log slow ops on secondaries. We've seen no reason to diverge from the usage of "slowMS", however, so we chose to use that threshold for secondary application logging as well. |
| Comment by Tess Avitabile (Inactive) [ 11/Oct/18 ] |
|
Thanks for the clarification. I agree that the secondary performance does not look like it is significantly impacted. It looks like mostly we are seeing noise in sys-perf, since performance went up in some cases and down in others. And since the call to now() did not show up in your linux-perf sample, it must not have been very lengthly. I am happy for you to proceed with this work. |
| Comment by Vesselina Ratcheva (Inactive) [ 11/Oct/18 ] |
|
tess.avitabile, these are all good questions! I'm sorry if I wasn't clear. 1) Both of the patches have the same changes. I just ran more than one to be sure, as the waterfall was a bit noisy. 2) The output metric itself represents secondary performance, measured by the number of documents applied per second. The workload disables replication on the secondary, only re-enabling it after the primary is done receiving and flushing all the writes, so that the secondary has to replicate them all at once. (More info here: documentation.) 3) Of course! I wrote a bare-bones clock-reads-only version to POC/test this, which can be found here. 4) It didn't show up in my output. Feel free to chime in if you have further questions/comments. The perf impact doesn't seem scary to me, but I'm totally open to discussion. |
| Comment by Tess Avitabile (Inactive) [ 11/Oct/18 ] |
|
Thanks, vesselina.ratcheva! I have a few follow-up questions. 1) Is there a difference between the Evergreen runs #1 and #2? 2) What does the output metric represent in the sys-perf tests? 3) Can I please see the patch build, so that I can see where and how the clock read was done? 4) Is it possible to see the clock read function call itself in the linux perf output, or was it so small that it didn't show up? |
| Comment by Vesselina Ratcheva (Inactive) [ 10/Oct/18 ] |
|
I ran some perf measurements for adding two clock reads to every op application and the effect on performance seemed somewhat noticeable, but not worrisome in my opinion. I chose to use the "fast clock source", since it offers acceptable precision for its low impact. Here are the secondary throughput results from Evergreen: (1: Local measurements were taken by running replica_sets_jscore_passthrough (which has 1 secondary) and waiting 15 seconds before intercepting the secondary's process with the linux perf tool. I've filtered in only the "syncApply" measurements (that's the affected method), showing the top 30 lines. (base: |
| Comment by Tess Avitabile (Inactive) [ 26/Apr/18 ] |
|
Re-triaging this ticket, since it was in the Support Grab Bag. |
| Comment by Eric Milkie [ 14/Dec/17 ] |
|
For this, we'll need to be careful not to impact performance by adding another two clock reads for every oplog entry. |
| Comment by Asya Kamsky [ 04/Dec/17 ] |
|
Agreed, it's rather difficult to debug (for example) secondary reads when you have to look on the primary logs to guess which replicated writes might be slow and therefore impacting read performance. |