Struggling to sort out publication performance problem

I’ve got a weird performance problem. My subscriptions take a really long time to run and I’m not sure why. I get basically the same behavior on local dev with a local DB as I do on galaxy with a compose.io db. It happens when I’m subscribing to fair amount of data - 6 different subscriptions returning a total of 215 documents that total to about 1.5MB of data. It takes around 30s to complete this subscription. I have another version that does this as a single subscription returning 6 cursors and it’s about the same.

The DB calls themselves run really fast (like returning the data in ~150ms) if I try them on a mongo client pointed at the same db. I’ve looked through the explain plans and they’re all using reasonable indices.

The publications are very vanilla, as so:
`
Meteor.publish(collection, function(planId) {
check(planId, String);
//check collection

const userId = this.userId;
if (!userId) {
  this.ready();
  return;
}

return collection.find({ planId });

});
`

Kadira gives me traces that show these horrible observe times

Those traces combined with watching the DDP closely on the client leaves me convinced that this is something going on in the server. I’m just at a loss for what could be wrong.

Any ideas?

Hm. So you are on 6 different collections? I’d try dropping them one by one first. Next I’d try scaling back each collection to one doc per sub and increase them individually by collection.

Do you have an index on planId? All publications should hit an index for the best performance.

Yes it has an index. The Queries run fast (~150ms when talking round trip from CA to AWS-east, much further than galaxy which is in the same data center) when run directly and I’ve checked the query plan pretty carefully and it looks like it’s using the right index.

How big are the documents that you are returning? Have you tried limiting the fields you’re returning to only what’s necessary?

So it does get worse with more data, so less data eventually makes the problem go away. But looking at that kadira trace. That’s 3 small docs (maybe 2k total). We know the query itself runs fast. How is the observer taking that long?

All the 215 docs together are around 1.5MB. So not tiny, but not that big. This is an initial load use case whereafter this it’s all in the client and it all runs smoothly. I need all the docs there completely to do that. But this doesn’t seem to be a normal slowdown from bandwidth.

If I run all 6 queries together on my california laptop pointing to the AWS-east compose mongo instance I can get all the complete docs back in ~800ms. So I’m not left with a sense that this is a traditional “make your query better/get less data” kind of bug.

Hmm, perhaps you could try using rawCollection. This would use the node driver directly. If you were to run the same queries using rawCollection and your performance were to increase it would mean that there is an underlying meteor issue.

Ok, so I wrote this very simple meteor method (note console.time and console.timeEnd monkey patched to work on server):

`
Meteor.methods({
planQuery: function(planId) {
check(planId, String);

const totalStr = 'Total query';
console.time(totalStr);
[Expenses, Employees, Revenues, Investments, Links, DynamicLinks].forEach(collection => {
  const str = `Querying ${collection._name}`;
  console.time(str);
  const objs = collection.find({ planId }).fetch();
  console.timeEnd(str);
  console.log(`Found ${objs.length} ${collection._name}`);
 });
console.timeEnd(totalStr);

}
});
`

I get this result:
I20160623-14:42:20.642(-7)? Querying expenses: 118ms
I20160623-14:42:20.643(-7)? Found 50 expenses
I20160623-14:42:20.806(-7)? Querying employees: 163ms
I20160623-14:42:20.806(-7)? Found 34 employees
I20160623-14:42:21.302(-7)? Querying revenues: 496ms
I20160623-14:42:21.303(-7)? Found 48 revenues
I20160623-14:42:21.314(-7)? Querying investments: 11ms
I20160623-14:42:21.315(-7)? Found 3 investments
I20160623-14:42:21.324(-7)? Querying links: 9ms
I20160623-14:42:21.324(-7)? Found 62 links
I20160623-14:42:21.329(-7)? Querying dynamicLinks: 6ms
I20160623-14:42:21.330(-7)? Found 22 dynamicLinks
I20160623-14:42:21.331(-7)? Total query: 805ms

So I think it’s pretty clear that it’s not query related, but something to do with the observers/publication system (or code that’s somehow sending that awry).

@andylash, did you ever get this figured out? I’m currently debugging a slow subscription.