0

NOTICE: I've also posted this to stackoverflow. I'm not sure where this question belongs. If it's not here, tell me, and i'll delete it.

I'm testing my replica set, in particular the read preference, and i'm still getting slow reads even with a nearest read preference set.

For the purpose of this question, we can just assume there are 2 mongodb instances (there are in fact 3). PRIMARY is in Amsterdam (AMS). SECONDARY is in Singapore (SG).

I also have 2 application servers in those 2 locations where I am running my test scripts (node+mongoose).

  1. From the AMS app server (so low latency with PRIMARY), if I run a simple find query, I get a response in under a second.
  2. However, If I run the same query from my app server in SG, I get response times of ~4-7 seconds.
  3. If I just connect to the SG SECONDARY from SG app server, my query times drop to <1s, similar to (1).

Going back to a standard rep set setting (with nearest), and if I look at the logs, I've noticed that if I send a query to SG using 'nearest', i can see the query in there, but I also see an entry for that same query (but fewer lines) in the PRIMARY log. But it is interesting that there is always an entry in the PRIMARY log even when querying the SECONDARY. I'm not sure if that is somehow related.

So, if I connect directly to the nearest machine, I get a response <1s, but when using the replica set, unless i'm next to the PRIMARY, responses times are >4s.

My question is then, why? Have I set up my replica server incorrectly. Is it a problem on the client side (mongoose/mongodb), or is it in fact working as it is mean to, and i've misunderstood how it works under the hood?

Here are my files (apologies for the wall of text):

test.js

mongoose.connect(configDB.url); 
var start = new Date().getTime();
Model.find({})
.exec(function(err, betas){
    var end = new Date().getTime();
    var time = end - start;
    console.log(time/1000);
    console.log('finished');
    console.log(betas.length);
});

config, also tried with server and replSet options

module.exports = {
    'url' : 'user:pwd@ip-primary/db,user:pwd@ip-secondary/db,user:pwd@ip-secondary/db'
}

Betas model

var betaSchema = mongoose.Schema({
    .. some fields
}, { read: 'n' });

And the log output from doing a read query as above from the SG app server:

LOG OF PRIMARY:

2015-09-16T07:49:23.120-0400 D COMMAND  [conn12520] run command db.$cmd { listIndexes: "betas", cursor: {} }
2015-09-16T07:49:23.120-0400 I COMMAND  [conn12520] command db.$cmd command: listIndexes { listIndexes: "betas", cursor: {} } keyUpdates:0 writeConflicts:0 numYields:0 reslen:296 locks:{ Global: { acquireC
ount: { r: 2 } }, MMAPV1Journal: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { R: 1 } } } 0ms

LOG OF SECONDARY

    2015-09-16T07:49:19.368-0400 D QUERY    [conn11831] [QLOG] Running query:
ns=db.betas limit=1000 skip=0
Tree: $and
Sort: {}
Proj: {}
2015-09-16T07:49:19.368-0400 D QUERY    [conn11831] Running query: query: {} sort: {} projection: {} skip: 0 limit: 1000
2015-09-16T07:49:19.368-0400 D QUERY    [conn11831] [QLOG] Beginning planning...
=============================
Options = INDEX_INTERSECTION KEEP_MUTATIONS
Canonical query:
ns=db.betas limit=1000 skip=0
Tree: $and
Sort: {}
Proj: {}
=============================
2015-09-16T07:49:19.368-0400 D QUERY    [conn11831] [QLOG] Index 0 is kp: { _id: 1 } io: { v: 1, key: { _id: 1 }, name: "_id_", ns: "db.betas" }
2015-09-16T07:49:19.368-0400 D QUERY    [conn11831] [QLOG] Index 1 is kp: { email: 1 } io: { v: 1, unique: true, key: { email: 1 }, name: "email_1", ns: "db.betas", background: true, safe: null }
2015-09-16T07:49:19.368-0400 D QUERY    [conn11831] [QLOG] Rated tree:
$and
2015-09-16T07:49:19.368-0400 D QUERY    [conn11831] [QLOG] Planner: outputted 0 indexed solutions.
2015-09-16T07:49:19.368-0400 D QUERY    [conn11831] [QLOG] Planner: outputting a collscan:
COLLSCAN
---ns = db.betas
---filter = $and
---fetched = 1
---sortedByDiskLoc = 0
---getSort = []
2015-09-16T07:49:19.368-0400 D QUERY    [conn11831] Only one plan is available; it will be run but will not be cached. query: {} sort: {} projection: {} skip: 0 limit: 1000, planSummary: COLLSCAN
2015-09-16T07:49:19.368-0400 D QUERY    [conn11831] [QLOG] Not caching executor but returning 109 results.
2015-09-16T07:49:19.368-0400 I QUERY    [conn11831] query db.betas planSummary: COLLSCAN ntoreturn:1000 ntoskip:0 nscanned:0 nscannedObjects:109 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:109 resl
en:17481 locks:{ Global: { acquireCount: { r: 2 } }, MMAPV1Journal: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { R: 1 } } } 0ms
  • The question definetly belongs here. Well, sort of. You might want to try mongoose.connect(configDB.url,{ replset: { strategy: 'statistical' }}). See mongoosejs.com/docs/guide.html#read for details. And please shoot a couple of requests (some 50), since we need a higher sample size to find out what's going on. – Markus W Mahlberg Sep 16 '15 at 18:03
  • Thanks for the advice. I've just run a couple of experiments (1k queries), which were interesting. The first query takes a long time, but this is then reduced substantially. I'll be posting the results up as an answer, unless that is a breach of etiquette. – Simon Sep 17 '15 at 11:03
1

So, after taking on board some advice and running a series of experiments with 1000 sequential queries, i.e., only 1 query at a time, waiting for the previous query to complete before sending another one, the avg query times (on the client side: make query and get results) show that I am actually not experiencing bad query times.

The first request (from SG) takes substantially longer than the others, going from 7s down to ~0.025. I can presume this is the client doing some work internally to figure out which member of the replica set to query.

The first request when run from AMS is substantially longer than the next 999 requests, but the difference is not as great, the first request being in the region of 0.8 seconds, vs an average of ~0.02 for the subsequent queries.

Here is the data for anyone interested. The collection only has ~100 documents.

Tests run from SG app server: avg over 1000 queries

Nearest + Ping 0.032815 seconds

Nearest + Statistical 0.041461 seconds

Primary + Ping 0.403152 seconds

Same data as above: avg over 999 queries - excludes 1st query

Nearest + Ping 0.02554054054 seconds

Nearest + Statistical 0.03429629629 seconds

Primary + Ping 0.39716516516 seconds

To compare, running the same Nearest + Ping test from AMS (avg over 1000 queries):

Nearest + Ping 0.023652 seconds

and over the last 999 queries:

Nearest + Ping 0.0228288288 seconds

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.