[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: PNG File base.png     PNG File evg1.png     PNG File evg2.png     PNG File withreads.png    
Issue Links:
Backports
Depends
Documented
is documented by DOCS-12178 Docs for SERVER-32146: Log slow oplog... Closed
Duplicate
is duplicated by SERVER-23253 Option to log slow replicated ops Closed
Related
is related to SERVER-44881 Giant slow oplog entries are being lo... Backlog
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: SERVER-32146 Log slow oplog entry application

(cherry picked from commit 66434ba0a7930efedbe5e06a098ab8e7bb659cfa)
Branch: v3.6
https://github.com/mongodb/mongo/commit/afb213ced669a328c90e0a0fb0b7e06bf92c0ccb

Comment by Githook User [ 11/Jan/19 ]

Author:

{'username': 'vessy-mongodb', 'email': 'vesselina.ratcheva@10gen.com', 'name': 'Vesselina Ratcheva'}

Message: SERVER-32146 Log slow oplog entry application

(cherry picked from commit 66434ba0a7930efedbe5e06a098ab8e7bb659cfa)
Branch: v4.0
https://github.com/mongodb/mongo/commit/3e27146079106a97aaea9d84109c7d699de75540

Comment by Githook User [ 25/Oct/18 ]

Author:

{'name': 'Vesselina Ratcheva', 'email': 'vesselina.ratcheva@10gen.com', 'username': 'vessy-mongodb'}

Message: SERVER-32146 Log slow oplog entry application
Branch: master
https://github.com/mongodb/mongo/commit/66434ba0a7930efedbe5e06a098ab8e7bb659cfa

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.)
On each row, the "size_N" suffix represents the document size, and "count_N" describes the number of documents. We should expect to see the clock reads have a more noticeable impact on the perf measurements for smaller documents.
The comparison is made against commits on the waterfall (I put down four to reduce noise).

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: , 2: ). Those were obtained by running the secondary_performance suite in the Linux 3-node variant (that particular suite only uses 2 nodes).

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: , with reads: )

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.

Generated at Thu Feb 08 04:29:19 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.