Catch up to oplog at most once per write fence #4694

OleksandrChekhovskyi · 2015-07-07T14:58:15Z

Before this change, number of catch-up attempts was N*M, where N is number of writes inside of the fence, and M is number of active observers on affected collections. Every catch up issues yet another query to find the latest oplog entry.

It was extremely inefficient, in terms of both CPU usage and added latency. After executing write-heavy methods, application process was occupied for many seconds doing the same thing over and over again.

This change provides a performance improvement for all kinds of workloads.

CPU profile of write-intensive method before the change:

After the change:

Before the change there was noticeable several seconds lag after the method invocation (which was caused by waitUntilCaughtUp function), before anything else could be processed. After the change that lag is gone, and application is responsive perceptively immediately after the operation is done.

The most visible effect is achieved when a method does a lot of writes, but this change improves efficiency all over the board.

glasser · 2015-07-07T20:50:19Z

This is super interesting. Do you have a benchmark or test that we can use to see the performance improvement you're describing?

glasser · 2015-07-07T21:00:52Z

packages/mongo/oplog_observe_driver.js

-      Meteor.defer(function () {
+
+      if (fence._oplogObserveDrivers) {
+        if (!_.contains(fence._oplogObserveDrivers, self))


This looks like it will lead to quadratic behavior. I'd rather give OplogObserveDrivers an incrementing ID and use an object to track them as a set.

Indeed. Fixed in new version of the patch.

OleksandrChekhovskyi · 2015-07-08T11:24:08Z

Patch has been updated to address the feedback.

I have created a simple benchmark that illustrates the problem.
https://github.com/OleksandrChekhovskyi/meteor-overhead-benchmark
Keep creating new pages with a button and observe how slow it can get.

glasser · 2015-07-08T18:01:21Z

packages/ddp-server/writefence.js

-      _.each(self.completion_callbacks, function (f) {f(self);});
-      self.completion_callbacks = [];
+      self.outstanding_writes++;
+      _.each(self.before_fire_callbacks, function (f) {f(self);});


I wonder if we need to think about what happens if one of these throws? We aren't for onAllCommitted callbacks, but (a) that's probably a mistake (b) the onBeforeFire callback in practice is more complex than the only existing onAllCommitted callback (eg, it blocks on network activity).

Added a try/catch to safeguard against unexpected exceptions.

glasser · 2015-07-08T18:20:38Z

Other than these last three comments, this change looks great. Your benchmark is pretty clear that this makes a difference, and it seems correct to me. It makes the WriteFence API a little stranger, but that API is a means to an end. Once you address those I think we should be able to merge this!

Also, if you'd like to add a description to History.md in the top v.NEXT under a new ### Livequery section that would be great.

Before this change, number of catch-up attempts was N*M, where N is number of writes inside of the fence, and M is number of active observers on affected collections. Every catch up issues yet another query to find the latest oplog entry. It was extremely inefficient, in terms of both CPU usage and added latency. After executing write-heavy methods, application process was occupied for many seconds doing the same thing over and over again. This change provides a performance improvement for all kinds of workloads.

OleksandrChekhovskyi · 2015-07-09T11:15:52Z

Patch has been updated, and hopefully everything is addressed now.

glasser · 2015-07-09T16:24:37Z

History.md

+
+* Improved server performance by reducing overhead of processing oplog after
+  database writes. Improvements are most noticeable in case when a method is
+  doing a lot of writes on collections with plenty of active observers.


add "#4694" here

glasser · 2015-07-09T16:32:09Z

Thanks, merged! This seems like it'll be a great performance increase and I'm excited to see it get out soon.

rclai · 2015-07-09T16:33:16Z

This is great because I do work with a lot of server-side observers.

mizzao · 2015-07-09T19:18:43Z

This is great, I first described this issue almost a year ago when we were still on the google groups and I'm very glad that someone fixed it.

https://groups.google.com/forum/#!topic/meteor-talk/Y547Hh2z39Y

Just wanted to point out that the solution proposed there was to "give up" if the oplog observer was too far behind, and just re-query the database to catch up. I'm not sure if that's what @OleksandrChekhovskyi did, but the benchmark seems to have proved something.

I guess this also illustrates why the google group was pretty useless for having these sorts of discussions. (> /dev/null)

zimme · 2015-07-10T05:59:13Z

👍

sebakerckhof · 2015-07-11T08:22:07Z

@mizzao No, the fallback you describe is already in Meteor since 1.0.4, see:
#2668

Instead, this PR should increase the oplog tailing performance for write-heavy loads, so that meteor doesn't have to use the fallback that fast.

In 1.0.4 there was however another PR merged that should also increase write performance with the oplog: https://github.com/meteor/meteor/pull/3697/commits

mizzao · 2015-07-11T14:22:15Z

@sebakerckhof excellent, thanks for all those links. I'm very grateful for all of the hardcore performance profilers out there - seems like they are really helping Meteor to grow into a robust and fast platform.

arunoda · 2015-07-11T23:26:55Z

This is great. Thanks @OleksandrChekhovskyi

arunoda · 2015-07-12T00:39:46Z

@glasser I got some idea while looking at this code base.
This solution pretty great and reduce oplog last entry checks to a few. But, there still an issue if we get a lot of method calls at once. Then updated messages delayed until we ping for oplog.

what if we can process waitUntilCaughtUp in a queue. So, then we can ping oplog once for a lot of waitUntilCaughtUp requests. And it's fairly simple to implement.

Is it sounds good or am I doing talking something wrong?

glasser · 2015-07-12T00:44:22Z

I'm not 100% sure what you're describing @arunoda but it sounds promising. As long as it doesn't err too far on the side of making the updated message come late because we're not trying for a while. Love to see a PR!

arunoda · 2015-07-12T00:47:44Z

It's a random idea. I'll give it a try today. May be not sure that really affect the performance changes. Let's see.

This bug was introduced by #4694 which switched OplogObserveDriver's listener from using beginWrite to the new onBeforeFire. beginWrite doesn't throw an error when called on a retired fence; onBeforeFire does. So don't try to interact with fired fences. (I'm not sure if there is an importance to the distinction between retired and fired introduced by dcd2641, but this code should be fine.) While we're at it, make the error in question (which shouldn't happen) be delivered to Mongo write callbacks (or thrown), if for no other reason than that it allows us to test this fix. Fixes #4839.

This bug was introduced by #4694 which switched OplogObserveDriver's listener from using beginWrite to the new onBeforeFire. beginWrite doesn't throw an error when called on a retired fence; onBeforeFire does. So don't try to interact with fired fences. (I'm not sure if there is an importance to the distinction between retired and fired introduced by dcd2641, but this code should be fine.) While we're at it, make the error in question (which shouldn't happen) be delivered to Mongo write callbacks (or thrown), if for no other reason than that it allows us to test this fix. Fixes #4839. Conflicts: packages/mongo/mongo_livedata_tests.js

glasser added the Project:Mongo Driver label Jul 7, 2015

glasser reviewed Jul 7, 2015
View reviewed changes

OleksandrChekhovskyi force-pushed the devel branch from 1dfc1f4 to d3e3877 Compare July 8, 2015 11:21

glasser reviewed Jul 8, 2015
View reviewed changes

OleksandrChekhovskyi force-pushed the devel branch from d3e3877 to 27bdf62 Compare July 9, 2015 11:06

glasser reviewed Jul 9, 2015
View reviewed changes

glasser closed this in cb4ba33 Jul 9, 2015

arunoda mentioned this pull request Jul 25, 2015

[perf] Check oplog last entry only at once globally #4816

Closed

Slava mentioned this pull request Jul 29, 2015

Adding callbacks to write fence after it has been armed in Oplog Driver #4839

Closed

arunoda mentioned this pull request Aug 28, 2015

ChangeFeed Improvements cloudant/meteor-couchdb#5

Closed

mikowals mentioned this pull request Nov 8, 2015

Just a question mikowals/pause-publish#1

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Catch up to oplog at most once per write fence #4694

Catch up to oplog at most once per write fence #4694

OleksandrChekhovskyi commented Jul 7, 2015

glasser commented Jul 7, 2015

glasser Jul 7, 2015

OleksandrChekhovskyi Jul 8, 2015

OleksandrChekhovskyi commented Jul 8, 2015

glasser Jul 8, 2015

OleksandrChekhovskyi Jul 9, 2015

glasser commented Jul 8, 2015

OleksandrChekhovskyi commented Jul 9, 2015

glasser Jul 9, 2015

glasser commented Jul 9, 2015

rclai commented Jul 9, 2015

mizzao commented Jul 9, 2015

zimme commented Jul 10, 2015

sebakerckhof commented Jul 11, 2015

mizzao commented Jul 11, 2015

arunoda commented Jul 11, 2015

arunoda commented Jul 12, 2015

glasser commented Jul 12, 2015

arunoda commented Jul 12, 2015

Catch up to oplog at most once per write fence #4694

Catch up to oplog at most once per write fence #4694

Conversation

OleksandrChekhovskyi commented Jul 7, 2015

glasser commented Jul 7, 2015

glasser Jul 7, 2015

Choose a reason for hiding this comment

OleksandrChekhovskyi Jul 8, 2015

Choose a reason for hiding this comment

OleksandrChekhovskyi commented Jul 8, 2015

glasser Jul 8, 2015

Choose a reason for hiding this comment

OleksandrChekhovskyi Jul 9, 2015

Choose a reason for hiding this comment

glasser commented Jul 8, 2015

OleksandrChekhovskyi commented Jul 9, 2015

glasser Jul 9, 2015

Choose a reason for hiding this comment

glasser commented Jul 9, 2015

rclai commented Jul 9, 2015

mizzao commented Jul 9, 2015

zimme commented Jul 10, 2015

sebakerckhof commented Jul 11, 2015

mizzao commented Jul 11, 2015

arunoda commented Jul 11, 2015

arunoda commented Jul 12, 2015

glasser commented Jul 12, 2015

arunoda commented Jul 12, 2015