New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

ddp match optimisation #3697

Closed
wants to merge 2 commits into
base: devel
from

Conversation

Projects
None yet
2 participants
@hypno2000

hypno2000 commented Feb 10, 2015

Hi,

We have ~100 write ops per second production site and this change helped me to speed up oplog tailing and reduce cpu usage in factor of 10. Before this change the bottle neck of mongo updates were meteor but now it seems it can keep up with mongo changes and the bottleneck is db.

It seems to work ok so far but can there be any side effect of this optimisation?

Thanks,
Reio

@glasser

This comment has been minimized.

Member

glasser commented Feb 11, 2015

Does it still have the same performance increase if written as:

   if (_.has(notification, 'collection') &&
       _.has(trigger, 'collection') &&
       ! EJSON.equals(notification.collection, trigger.collection)) {
     return false;
   }
   if (_.has(notification, 'id') &&
       _.has(trigger, 'id') &&
       ! EJSON.equals(notification.id, trigger.id)) {
     return false;
   }

That's exactly the same semantics as the current code, whereas yours has some subtle differences.

If that isn't as good as your version, what about this one:

   if (_.has(notification, 'collection') &&
       _.has(trigger, 'collection') &&
       ! EJSON.equals(notification.collection, trigger.collection)) {
     return false;
   }
   if (_.has(notification, 'id') &&
       _.has(trigger, 'id') &&
       notification.id !== trigger.id) {
     return false;
   }

This actually doesn't have the same semantics (it won't work with Mongo ObjectIDs) but I'm just trying to figure out which part here is causing the problem.

@glasser

This comment has been minimized.

Member

glasser commented Feb 11, 2015

(And if you can show me a good reproduction/benchmark that highlights your differences, that would be great!)

@hypno2000

This comment has been minimized.

hypno2000 commented Feb 11, 2015

There is one browser tab open subscribing 30 docs from test collection with limit and sorting. The modified document is also one of those docs subscribed. The test command in mongo shell is:

for (var i = 1; i <= 10000; i++) {
  db.test.update({_id: 'XpXqRm8svMjwrsEwk'}, {$set: {amount: i}});
  print(i);
}

The time's are in milliseconds. process is self._oplogTailConnection.tailcallback function exec time. process: fire is crossbar.fire exec time. The time is total time spent.

Meteor original:

I20150211-17:03:58.353(2)? {
I20150211-17:03:58.355(2)?   "process": {
I20150211-17:03:58.355(2)?     "time": 15434.184,
I20150211-17:03:58.356(2)?     "count": 10000,
I20150211-17:03:58.356(2)?     "min": 1.249,
I20150211-17:03:58.356(2)?     "max": 21.031,
I20150211-17:03:58.356(2)?     "avg": 1.543
I20150211-17:03:58.356(2)?   },
I20150211-17:03:58.356(2)?   "process: fire": {
I20150211-17:03:58.356(2)?     "time": 15341.753,
I20150211-17:03:58.356(2)?     "count": 10000,
I20150211-17:03:58.356(2)?     "min": 1.241,
I20150211-17:03:58.356(2)?     "max": 21.008,
I20150211-17:03:58.356(2)?     "avg": 1.534
I20150211-17:03:58.356(2)?   }
I20150211-17:03:58.356(2)? }

Pull request:

I20150211-17:11:20.045(2)? {
I20150211-17:11:20.047(2)?   "process": {
I20150211-17:11:20.048(2)?     "time": 2640.848,
I20150211-17:11:20.048(2)?     "count": 10000,
I20150211-17:11:20.048(2)?     "min": 0.006,
I20150211-17:11:20.048(2)?     "max": 18.034,
I20150211-17:11:20.048(2)?     "avg": 0.264
I20150211-17:11:20.048(2)?   },
I20150211-17:11:20.048(2)?   "process: fire": {
I20150211-17:11:20.048(2)?     "time": 2501.352,
I20150211-17:11:20.049(2)?     "count": 10000,
I20150211-17:11:20.049(2)?     "min": 0.001,
I20150211-17:11:20.049(2)?     "max": 18.011,
I20150211-17:11:20.049(2)?     "avg": 0.25
I20150211-17:11:20.049(2)?   }
I20150211-17:11:20.050(2)? }

Yours first:

I20150211-17:10:32.916(2)? {
I20150211-17:10:32.917(2)?   "process": {
I20150211-17:10:32.917(2)?     "time": 8890.843,
I20150211-17:10:32.917(2)?     "count": 10000,
I20150211-17:10:32.917(2)?     "min": 0.693,
I20150211-17:10:32.917(2)?     "max": 12.273,
I20150211-17:10:32.917(2)?     "avg": 0.889
I20150211-17:10:32.917(2)?   },
I20150211-17:10:32.917(2)?   "process: fire": {
I20150211-17:10:32.917(2)?     "time": 8796.623,
I20150211-17:10:32.917(2)?     "count": 10000,
I20150211-17:10:32.917(2)?     "min": 0.687,
I20150211-17:10:32.917(2)?     "max": 12.255,
I20150211-17:10:32.917(2)?     "avg": 0.88
I20150211-17:10:32.918(2)?   }
I20150211-17:10:32.918(2)? }

Yours second:

I20150211-17:08:49.982(2)? {
I20150211-17:08:49.982(2)?   "process": {
I20150211-17:08:49.982(2)?     "time": 9095.918,
I20150211-17:08:49.982(2)?     "count": 10000,
I20150211-17:08:49.982(2)?     "min": 0.692,
I20150211-17:08:49.983(2)?     "max": 27.558,
I20150211-17:08:49.983(2)?     "avg": 0.91
I20150211-17:08:49.983(2)?   },
I20150211-17:08:49.983(2)?   "process: fire": {
I20150211-17:08:49.983(2)?     "time": 8998.457,
I20150211-17:08:49.983(2)?     "count": 10000,
I20150211-17:08:49.983(2)?     "min": 0.683,
I20150211-17:08:49.983(2)?     "max": 27.54,
I20150211-17:08:49.983(2)?     "avg": 0.9
I20150211-17:08:49.983(2)?   }
I20150211-17:08:49.983(2)? }
@glasser

This comment has been minimized.

Member

glasser commented Feb 11, 2015

Nice benchmark ... is it from your big app or is it a standalone thing that I can try?

Let me suggest something else that might get closer to the PR while still working in a few extra cases.

@glasser

This comment has been minimized.

Member

glasser commented Feb 11, 2015


if (typeof(notification.collection) === 'string' &&
    typeof(trigger.collection) === 'string' &&
    notification.collection !== trigger.collection) {
  return false;
}

if (typeof(notification.id) === 'string' &&
    typeof(trigger.id) === 'string' &&
    notification.id !== trigger.id) {
  return false;
}

if (notification.id instanceof LocalCollection._ObjectID &&
    trigger.id instanceof LocalCollection._ObjectID &&
    ! notification.id.equals(trigger.id)) {
  return false;
}
@hypno2000

This comment has been minimized.

hypno2000 commented Feb 12, 2015

Its from the big app and its using a benchmark tool thats fairly simple but its using inhouse made typescript compiler. I can publish these to atmosphere but i dont want to release it undocumented. Easier just to share the compiled js of the benchmark tool. I'll make clean public example test project tomorrow, 2am here atm.

@hypno2000

This comment has been minimized.

hypno2000 commented Feb 12, 2015

Your last code is basically as fast as the original pull request code. Have changed the pull request to this one for now.

glasser added a commit that referenced this pull request Feb 12, 2015

crossbar: check common reasons to not match first
Also, put off the use of EJSON.equals until necessary.

Inspired by @hypno2000.  See #3697.
@glasser

This comment has been minimized.

Member

glasser commented Feb 12, 2015

OK, I pushed to devel a version of my code with comments and such.

I have another idea of a way to speed up this file, let me code it up and you can test it...

@glasser glasser closed this Feb 12, 2015

@glasser

This comment has been minimized.

Member

glasser commented Feb 12, 2015

@hypno2000 Can you try the branch crossbar-collection-index (or just the head commit cherry-picked onto whatever version of Meteor you're using) and tell me if that makes a noticeable difference? Note that it is built on top of the previous commit you tested.

(Assuming that your benchmark has a bunch of different collections.)

@hypno2000

This comment has been minimized.

hypno2000 commented Feb 12, 2015

crossbar-collection-index is fast:

I20150212-09:46:27.175(2)? {
I20150212-09:46:27.175(2)?   "crossbar.fire": {
I20150212-09:46:27.175(2)?     "time": 1918.373,
I20150212-09:46:27.175(2)?     "count": 10000,
I20150212-09:46:27.175(2)?     "min": 0.164,
I20150212-09:46:27.175(2)?     "max": 3.606,
I20150212-09:46:27.175(2)?     "avg": 0.192
I20150212-09:46:27.176(2)?   }
I20150212-09:46:27.176(2)? }

Its impressive that while running this test with mongo shell and browser windows side by side the number in browser and print command in mongo shell changing in sync, no lagging behind at all. Before browser was lagging more than 10 seconds behind.

@glasser

This comment has been minimized.

Member

glasser commented Feb 12, 2015

Great to hear. And I'm guessing (can you confirm?) that removing the fast-path block about collection from the previous commit (though not the fast-path blocks about id) shouldn't make a difference?

@hypno2000

This comment has been minimized.

hypno2000 commented Feb 13, 2015

Yes, removing this:

    if (typeof(notification.collection) === 'string' &&
        typeof(trigger.collection) === 'string' &&
        notification.collection !== trigger.collection) {
      return false;
    }

has no effect as now it only iterates through matching collection listeners.

glasser added a commit that referenced this pull request Feb 13, 2015

"Index" crossbar by collection
ie, when processing each oplog entry, don't even look at the triggers
from unrelated collection.

In practice, all notifications and triggers have string `collection`s.
So the support code for non-string or missing collection probably
doesn't get used other than in tests. But it seems like a good idea to
keep the interface hypothetically generic.

Summary: apparently much faster for at least one real user, see #3697  Note that all the special-casing in _match was also added as part of feedback on that PR.  FWIW this file should be completely self-contained and documenting so even if you don't know what it's used for, I hope you can review the change, which should be purely a performance optimization

Test Plan: unit tests

Reviewers: ekatek

Differential Revision: https://phabricator.meteor.io/D29

glasser added a commit that referenced this pull request Feb 13, 2015

"Index" crossbar by collection
ie, when processing each oplog entry, don't even look at the triggers
from unrelated collection.

Also, just make "every trigger and notification needs a string
collection" into a hard rule.

This is apparently much faster for at least one real user; see #3697.

Summary: should be self-contained and documented

Test Plan: unit tests

Reviewers: ekatek

Differential Revision: https://phabricator.meteor.io/D29

glasser added a commit that referenced this pull request Feb 13, 2015

"Index" crossbar by collection
ie, when processing each oplog entry, don't even look at the triggers
from unrelated collection.

Also, just make "every trigger and notification needs a string
collection" into a hard rule.

This is apparently much faster for at least one real user; see #3697.

Summary: should be self-contained and documented

Test Plan: unit tests

Reviewers: ekatek

Differential Revision: https://phabricator.meteor.io/D29

glasser added a commit that referenced this pull request Feb 13, 2015

"Index" crossbar by collection
ie, when processing each oplog entry, don't even look at the triggers
from unrelated collection.

Also, just make "every trigger and notification needs a string
collection" into a hard rule.

This is apparently much faster for at least one real user; see #3697.

Summary: should be self-contained and documented

Test Plan: unit tests

Reviewers: ekatek

Differential Revision: https://phabricator.meteor.io/D29
@glasser

This comment has been minimized.

Member

glasser commented Feb 13, 2015

Great, I merged in a simpler version of that change. Thanks for profiling this @hypno2000 !

cscott added a commit to cjb/codex-blackboard that referenced this pull request Jan 10, 2016

Upgrade to Meteor 1.0.4.2.
Meteor release notes:
http://info.meteor.com/blog/meteor-104-mongo-cordova-template-subscriptions
https://github.com/meteor/meteor/blob/release/METEOR@1.0.4.2/History.md

Important performance improvements included in this release:
* If the oplog observe driver gets too far behind in processing the oplog,
  skip entries and re-poll queries instead of trying to keep up.
  meteor/meteor#2668
* Optimize common cases faced by the "crossbar" data structure (used by
  oplog tailing and DDP method write tracking).
  meteor/meteor#3697
* The oplog observe driver recovers from failed attempts to apply the
  modifier from the oplog (eg, because of empty field names).
* Avoid unnecessary work while paused in minimongo.
* Fix bugs related to observing queries with field filters: changed
  callbacks should not trigger unless a field in the filter has
  changed, and changed callbacks need to trigger when a parent of an
  included field is unset.
  meteor/meteor#2254

There are also API improvements which can lead to more efficient/less
mistake-prone subscriptions and observe.  We'll migrate to these new
APIs in the next few commits.

Change-Id: I58e464750a03d9cfedfa7f07c9e25e8a6460fcde
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment