I am experiencing very often mongo queries from meteor taking 1-2s or sometimes even more. There queries are find by id(primary key) or insert. I have also enabled slow query log in mongodb for queries taking more than 50ms but I dont see these queries getting logged here.
I am using kadira for monitoring, and i have also debugged using log statement to check how much time queries took.
Also CPU usage in my server is consistently 30-40%. can it be because of that meteor is taking time?
There is a high chance that one of your meteor methods or publish is taking a lot of time. Check your observers and method response times in kadira. Or use the meteor-dev-tools to see if you are publishing a huge number of documents by mistake.
If the query is running in a server method put a console.log before and after the mongo find to see if mongo is at fault. It is probable not mongo at fault but worth checking.
If you are return entire collections e.g. find({}) then it will take time for the server to transmit the object to the client and for the client to process it.
If it is a publication, you can use the same console log trick as above to determine if it’s the server taking the time or the passing of the information to the client.
If I had to guess, i would say you are subscribing to the publication with {} as the default search criteria. This means it tries to download the entire collection whenever the subscription starts. My workaround would be to initialise the publication with a particular _id to search for and change this later in your client side code to the id(s) you actually want to lookup.
It was meteor method, not publication. Below is part of code from method.
Meteor.call('conversations.on_new_message', conv_id, time, true);
if(tData && tData.data && tData.data.isDummy) {
time = time - 1000;
//insert agent msg as trigger
tData.msg.fields.company = companyId;
tData.msg.fields.device = device;
tData.msg.fields.conv_id = conv_id;
tData.msg.fields.msg_type = MessageType.AGENT_TRIGGER_QUESTION;
tData.msg.fields.msg_time = time;
tData.msg.fields.isBotMsg = true;
tData.msg.fields.view_state = 'READ';
tData.msg.fields.view_time = tData.msg.fields.msg_time;
//tData.msg.fields.sender_id = null;
tData.msg.fields.payload._type = MessageType.AGENT_TRIGGER_QUESTION;
delete(tData.msg.fields.payload.texts);
Messages.insert(tData.msg.fields);
}
let msg_id = Messages.insert(message);
// update conversation's unread count
let curr_user = Meteor.call('chat-users.getById', chat_user_id, companyId);
on_new_message method
'conversations.on_new_message'(conversationId:string, msg_time:number, isVisitorMessage:boolean) {
Meteor.call('logger.info', 'conversations.on_new_message conv=%s isV=%s', conversationId, isVisitorMessage);
let toUpdate = {$set:{last_msg_time: msg_time}};
if(isVisitorMessage) {
toUpdate.$set.state = ConvState.ACTIVE;
toUpdate.$inc = { unread_msg_count: 1 };
}
const doAutoincrement = function(collection, callback) {
collection.rawCollection().findAndModify(
{ _id: conversationId},
[],
toUpdate ,
{ new: true},
callback
);
}
return Meteor.wrapAsync(doAutoincrement)(Conversations);
},
chat-users.getById method
'chat-users.getById'(userId:string,companyId:string) {
Meteor.call('logger.info', 'chat_uid=%s companyId=%s chat-users.getById', userId, companyId);
return ChatUsers.findOne({_id:userId,company:companyId});
},
so between 2 log lines there are 3 mongo queries(2 insert, 1 update which finds by id) which took 4s as per console log. it usually takes long and kadira also shows that method is taking long time. it also shows db query took time.
Put a console.log message directly before and after each mongo query. Also wrap your logger messages with console.log and check the time stamp in the meteor log at the console. Pinpoint whatever is slow and debug from there.
I would suspect the delay to be in the autoincrement query. Is last_msg_time in an index? Why are you not just using an update query instead of find And Modify?
Chatusers? Is id and company I’d in an index? Is companyid required? Is _id not unique?
Try without the logger.info calls to see if it makes any difference.
Let me try putting console.log directly below and above the query.
I have put log statement just below and above autoincrement query and it also took roughly 1/4th of time(which is significant)
last_msg_time is not index, is it required? since in findAndModify find is by _id (which is primary/uniqye key) so it should be fast. In some cases I needed to increment and then get updated value so I used this query, which I certainly dont need here and can use update instead.
In chatusers _id is index and its unique as well,(_id is index by default in mongo). companyid is used only to make sure if malicious user sends incorrect companyid, we dont do an update. Will it make any difference to performance?
logger.info method just logs using winston logger. Will it also make a difference?
Thanks a lot for help.
There is never a magic fix. You need to work on all the queries one by one and optimise them.
The way I optimise queries is out with meteor using robomongo. Paste in a sample query and see how it performs. If it is slow, use the explain command to determine if it is actually using the index you think it is using. It probably isn’t.
I can’t really say that removing the logger call will make any difference. Comment them out and try.
Yes that is the way to test. Thanks for robomongo suggestion, will try it.
My suspect was meteor because if db would have been slow, i would see it in mongodb slow query log. I have enabled slow query log for above 50ms queries. Kadira shows query taking 150ms+ but no log in slow query log.
Maybe its because of some other reason. need to find it out.
Just an update:
insert in other collection is fast, while insert in messages collection is consistently slow(I suppose not from db because its not in slow query log)
messages collection is subscribed by huge number of visitors, so live queries is being maintained by meteor. Further I am running single mongodb instance, so there is no replication and oplog notification. Would it cause insert to be slow?
Yes. Without oplog, you’re using Meteor’s poll-and-diff, which means up to ten seconds for subscribers to be notified of changes - plus a huge overhead in computing those changes.
Read more here:
You could consider cultofcoders:redis-oplog as an alternative.
Thanks! I thinks this must be the reason for slow insert performance on messages collection.