Ближайший параметр чтения набора реплик по-прежнему работает медленно

ВНИМАНИЕ: я также опубликовал это на dba.stackexchange.com. . Я не уверен, к чему относится этот вопрос. Если его здесь нет, скажите мне, и я удалю его.

Я тестирую свой набор реплик, в частности предпочтение чтения, и я все еще получаю медленное чтение даже с ближайшим набором предпочтений чтения.

Для целей этого вопроса мы можем просто предположить, что существует 2 экземпляра mongodb (на самом деле их 3). PRIMARY находится в Амстердаме (AMS). SECONDARY находится в Сингапуре (SG).

У меня также есть 2 сервера приложений в тех 2 местах, где я запускаю свои тестовые сценарии (узел + мангуст).

  1. С сервера приложений AMS (такая низкая задержка с PRIMARY), если я запускаю простой поисковый запрос, я получаю ответ менее чем за секунду.
  2. Однако, если я запускаю тот же запрос с моего сервера приложений в SG, я получаю время ответа ~ 4-7 секунд.
  3. Если я просто подключусь к SG SECONDARY с сервера приложений SG, время моего запроса упадет до ‹1 с, аналогично (1).

Возвращаясь к стандартной настройке набора представителей (с ближайшим), и если я посмотрю журналы, я заметил, что если я отправлю запрос в SG, используя «ближайший», я могу увидеть запрос там, но я также вижу запись для того же запроса (но меньше строк) в ОСНОВНОМ журнале. Но интересно, что в ПЕРВИЧНОМ логе всегда есть запись, даже при запросе ВТОРИЧНОГО. Я не уверен, что это как-то связано.

Итак, если я подключаюсь напрямую к ближайшей машине, я получаю ответ ‹1 с, но при использовании набора реплик, если я не нахожусь рядом с ОСНОВНЫМ, время ответов составляет> 4 с.

Тогда у меня возникает вопрос, почему? Я неправильно настроил свой сервер-реплику. Это проблема на стороне клиента (mongoose/mongodb), или это на самом деле работает так, как задумано, и я неправильно понял, как это работает под капотом?

Вот мои файлы (извините за стену текста):

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, также пробовал с параметрами server и replSet

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

Бета-модель

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

И вывод журнала выполнения запроса на чтение, как указано выше, с сервера приложений SG:

ЖУРНАЛ ПЕРВИЧНОГО:

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

ВТОРИЧНЫЙ ЖУРНАЛ

    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

person Simon    schedule 16.09.2015    source источник


Ответы (1)


Информация в ваших выходных данных указывает на то, что сервер базы данных быстро обрабатывает запрос. Таким образом, эта проблема, скорее всего, будет лежать вне самой базы данных, возможно, в клиенте.

Вы запускаете один и тот же запрос несколько раз и синхронизируете каждое выполнение?

Я подозреваю, что это может быть связано с некоторым первоначальным обнаружением со стороны вашего клиента MongoDB - как узнать, что является ближайшим, прежде чем отвечать, если он изначально не попадает в каждый узел и не определяет время ответов?

person daveh    schedule 17.09.2015
comment
Ага. Запуск эксперимента с 1000 последовательных запросов (следующий начинается только после завершения предыдущего) демонстрирует, что первый запрос работает медленно. Последующие проходят с приемлемой скоростью. - person Simon; 17.09.2015