CPU thrashing seemingly related to oplog tailing

My app is connected to 2 databases with oplog tailing enabled for both connections. The secondary connection is using maxfi:remote-collection@0.3.0 to create the connection.

Every 30 mins throughout the day external services do an ETL to update the secondary database from a third-party service. Usually there’s less than 500 documents inserted/updated/removed, except for one aggregation that has an $out stage that outputs about 30,000 documents. There’s also another ETL process that updates one document approx every second.

The issue is that, with oplog tailing enabled on the secondary database connection, the meteor apps CPU starts thrashing for almost 3 minutes. The strange thing is that the app doesn’t even publish or observe the large aggregations output collection, which I assume could otherwise be a problem, and as far as I’m aware meteor doesn’t create oplog notifications for $out aggregations anyway… The other db updates seem minimal enough that meteor shouldn’t freak out. Furthermore, I can’t see any oplog notifications or observer changes in the APM.

I’ve tested the ETL with oplog tailing disabled on the secondary collection and the issue appears to be resolved. However, I’m wondering what’s going on here and why the CPU thrashing occurs with oplog tailing enabled, even though the app isn’t observing most of the updates. Any insights would be greatly appreciated!

Below are some screenshots from Galaxy, APM and MongoDB Atlas as well as some more info about the infrastructure and the app.

With oplog tailing enabled on the secondary DB

With oplog tailing disabled on the secondary DB




Infrastructure

Hosting

Meteor Galaxy

MongoDB

MongoDB Atlas version 3.6.6 M10 2GB RAM

Meteor

METEOR@1.7.0.3

.meteor/versions

accounts-base@1.4.2
accounts-password@1.5.1
alanning:roles@1.2.16
allow-deny@1.1.0
anti:i18n@0.4.3
aslagle:reactive-table@0.8.45
autoupdate@1.4.0
babel-compiler@7.1.1
babel-runtime@1.2.2
base64@1.0.11
binary-heap@1.0.10
blaze@2.3.2
blaze-html-templates@1.1.2
blaze-tools@1.0.10
boilerplate-generator@1.5.0
caching-compiler@1.1.12
caching-html-compiler@1.1.2
callback-hook@1.1.0
ccorcos:subs-cache@0.9.6
check@1.3.1
coffeescript@2.2.1_1
coffeescript-compiler@2.2.1_1
ddp@1.4.0
ddp-client@2.3.2
ddp-common@1.4.0
ddp-rate-limiter@1.0.7
ddp-server@2.2.0
deanius:promise@3.1.4
deps@1.0.12
diff-sequence@1.1.0
dynamic-import@0.4.1
easy:search@2.2.1
easysearch:components@2.2.1
easysearch:core@2.2.0
ecmascript@0.11.1
ecmascript-runtime@0.7.0
ecmascript-runtime-client@0.7.1
ecmascript-runtime-server@0.7.0
ejson@1.1.0
email@1.2.3
es5-shim@4.8.0
force-ssl@1.1.0
force-ssl-common@1.1.0
geojson-utils@1.0.10
hot-code-push@1.0.4
html-tools@1.0.11
htmljs@1.0.11
http@1.4.1
id-map@1.1.0
jagi:astronomy@1.2.11
jquery@1.11.11
jss:publish-authorized@0.2.3
kadira:blaze-layout@2.3.0
kadira:flow-router@2.12.1
launch-screen@1.1.1
less@2.7.12
livedata@1.0.18
lmieulet:meteor-coverage@1.1.4
localstorage@1.2.0
logging@1.1.20
maxfi:remote-collection@0.3.0
maxfi:semantic-ui-components@0.1.0
maxfi:semantic-ui-css@2.2.14
mdg:meteor-apm-agent@3.1.1
meteor@1.9.0
meteor-base@1.4.0
meteorhacks:meteorx@1.4.1
meteorhacks:picker@1.0.3
meteorhacks:subs-manager@1.6.4
meteortesting:browser-tests@1.0.0
meteortesting:mocha@1.0.0
minifier-css@1.3.1
minifier-js@2.3.5
minimongo@1.4.4
mnmtanish:call@1.1.1
mobile-experience@1.0.5
mobile-status-bar@1.0.14
modern-browsers@0.1.1
modules@0.12.0
modules-runtime@0.10.0
momentjs:moment@2.14.4
mongo@1.5.0
mongo-dev-server@1.1.0
mongo-id@1.0.7
mongo-livedata@1.0.12
npm-bcrypt@0.9.3
npm-mongo@3.0.7
numeral:numeral@1.5.3_1
observe-sequence@1.0.16
ongoworks:security@1.3.0
ordered-dict@1.1.0
peerlibrary:assert@0.2.5
peerlibrary:base-component@0.16.0
peerlibrary:blaze-components@0.22.0
peerlibrary:computed-field@0.9.0
peerlibrary:data-lookup@0.2.1
peerlibrary:reactive-field@0.4.0
practicalmeteor:mocha-core@1.0.1
promise@0.11.1
random@1.1.0
rate-limit@1.0.9
reactive-dict@1.2.0
reactive-var@1.0.11
reload@1.2.0
remcoder:chronos@0.5.0
retry@1.1.0
routepolicy@1.0.13
rzymek:moment-locale-en-au@2.14.1
sakulstra:aggregate@1.4.3
service-configuration@1.0.11
session@1.1.7
sha@1.0.9
shell-server@0.3.1
socket-stream-client@0.2.2
spacebars@1.0.15
spacebars-compiler@1.1.3
srp@1.0.10
standard-minifier-css@1.4.1
standard-minifier-js@2.3.4
stevezhu:lodash@3.10.1
templating@1.3.2
templating-compiler@1.3.3
templating-runtime@1.3.2
templating-tools@1.1.2
tracker@1.2.0
ui@1.0.13
underscore@1.0.10
url@1.2.0
webapp@1.6.1
webapp-hashing@1.0.9
zodiase:function-bind@0.0.1

Meteor is simply tailing the oplog, so the server would get notified for all operations. Subsequently, Meteor decides which observers are affected by these operations.

It seems that while there are no observers in your case that would be affected by the batch operations, the number of oplog entries created by the batch operations are enough to overwhelm the Node.js process. While this hasn’t been a problem in my setup, a lot depends on the cpu power available to your Node.js process. Also, maybe you are missing some Observers that are getting affected by these operations? It has happened to me earlier :slight_smile:

Architecturally it makes sense to separate the “reactive” and “non-reactive” collections like you’ve done to avoid the problem. The other option would be to use something like redis-oplog for your app’s reactive updates instead of Mongo oplog.

2 Likes

I would be surprised if $out doesn’t create oplog notifications; doing aggregations via $out writes the result to a special read-only collection.

Even if you don’t have any observes on a particular collection, for every oplog notification you are going to have the overhead of BSON deserialization and a number of EJSON.clone calls, both of which are extremely CPU intensive.

How many observes do you have on this secondary database? Disabling the oplog for the secondary database might be a reasonable solution if you don’t have many observes on that database.

Could you do the aggregation without using the $out operator? That would prevent all the oplog notifications coming in.

1 Like

Thanks @gaurav7 and @veered.

I was under the impression that meteor would ignore oplog changes from an aggregation with the $out pipeline stage:

OplogObserveDriver doesn’t handle renameCollection operations (used by aggregation with $out) · Issue #4947 · meteor/meteor

I guess that makes sense that it would need to translate oplog entries to EJSON to know if any observers are affected by those operations.

As far as I can tell I only have 3 observers (publications) on the secondary database. However, they are for small collections with minimal changes. If I have missed some, would this show in APM under “Oplog Notifications” or “Observer Changes”?

redis-oplog looks super cool but I’m reluctant to use it at the moment because it would require a considerable amount of refactoring of the ETL services.

What I could perhaps do instead of using the $out stage is to take the aggregation result and diff it with what’s already in the database, as the data doesn’t change much, and then only insert/update/remove as required. Perhaps it’s possible to use the same diff algorithm that meteor uses in it’s PollingObserveDriver? This would, however, increase load on the server currently running the aggregation but that shouldn’t be an issue in my particular setup.

On a more general note, how would one generally diagnose this type of issue? I would have expected APM to show a large number of oplog notifications, or does it only show oplog notifications for observers? How would one debug this on galaxy?


For now, having disabled the oplog on the secondary connection appears to have resolved the issue. However, I’d love to get a better understanding of this to avoid this type of issue in the future.


On a side note, would the increase in the “scanned objects” (green line) and continued higher levels be due to the $out stage writes?

That question reminded me that Kadira’s documentation had a section on this. Turns out that those docs are now available in Galaxy’s guide: https://galaxy-guide.meteor.com/apm-optimizing-your-app-for-live-queries.html (section ‘Prevent unwanted oplog notifications’). It seems to be addressing a scenario very similar to yours, and also recommends separating the databases like you’ve done.

The guide suggests that if the trend of “Oplog Notifications” doesn’t match the trend of “Observer Changes”, then there are oplog notifications not needed by the app (the ones that account for the difference), and hence can be moved to a non-oplog database. So conversely, if their trends match then the app has Observers that are getting affected by oplog notifications. I think you should be able to see such Observers in the ‘Publications Breakdown’ section

1 Like

My understanding is that APM would show all oplog notifications. So, if the number is small for you and you’re still facing those issues then that’s indeed strange. Try profiling your app when this happens? @veered and co. have released a useful package for that: https://github.com/qualialabs/profile

Definitely feels like disabling oplog tailing is the way to go here. If you want to double check how many observes you have that are currently using the oplog vs polling driver, check out https://github.com/qualialabs/analyze-observes

If you take this approach, then I don’t think you will have to change any of your code; relying on $out in this case seems totally fine.

I expect that the bump in scanned objects is likely to rerunning the aggregation. Does that bump coincide with rerunning the aggregation?

And Kadira does not show all oplog notifications. In fact, it doesn’t even display oplog notifications for all observes. It only shows oplog notifications associated with publications.

@gaurav7 thanks for the qualia:profile callout :slight_smile:

1 Like