Почему MongoDB (или node-mongodb-native) снижает производительность до одной операции на соединение в секунду? - PullRequest
Новая
       27

Почему MongoDB (или node-mongodb-native) снижает производительность до одной операции на соединение в секунду?

0 голосов
/ 22 марта 2019

Я уже давно пытаюсь решить мою проблему без какого-либо успеха. Ни один не нашел я подобный вопрос здесь. Я сталкиваюсь с проблемой времени отклика, когда я отправляю 20 запросов агрегации в mongod, и для выполнения всех 20 запросов требуется более 5 секунд, в то время как каждая отдельная агрегация решается в течение 1 мс. Я ожидаю, что код будет работать под 50 мс.

Одна из основных проблем заключается в том, что результаты поступают в виде блоковых блоков с явной видимой задержкой в ​​1 секунду. Я получаю 1 результат за соединение в секунду. Каждую секунду создается дополнительное соединение, поэтому я получаю 1,2,3,4,5 результатов в секунду.

После многих попыток я могу ограничить проблему mongod. Я использовал приведенный ниже код node.js на 3 разных машинах, в то время как на локальном компьютере я получаю эту диспетчеризацию блоков и общее время выполнения более 5 секунд. На двух других машинах результат завершается за <50 мс, без каких-либо блоков и тех 1-секундных задержек в той же базе данных. </p> 

//console output - you can see the block dispatch.
//first section connects to mongod and send 20x the same quarry to mongod
18:16:25.440Z  INFO WS BOT/test3.js: MONGO SUCCESFULLY CONNECTED!
18:16:25.441Z DEBUG WS BOT/test3.js: 0 Start... %dms
//(...) while loop to send the aggregations to mongod finished in about 10ms - which is fine. 
18:16:25.450Z DEBUG WS BOT/test3.js: 18 Start... %dms
18:16:25.451Z DEBUG WS BOT/test3.js: 19 Start... %dms

//now the results of the mongo aggregations should come:

// First Block dispatch - 14ms after the request. Which is fine! But only 1 of 20 request
18:16:25.455Z DEBUG WS BOT/test3.js: 0 End... 0s 14.150247ms

// Second Block dispatch - 1 second 14ms after the request. 2 Results.
18:16:26.475Z DEBUG WS BOT/test3.js: 1 End... 1s 28.834198ms
18:16:26.476Z DEBUG WS BOT/test3.js: 2 End... 1s 28.880778ms

// Third Block dispatch - 2 seconds after the request. 3 Results.
18:16:27.486Z DEBUG WS BOT/test3.js: 3 End... 2s 38.423885ms
18:16:27.487Z DEBUG WS BOT/test3.js: 5 End... 2s 38.926009ms
18:16:27.488Z DEBUG WS BOT/test3.js: 4 End... 2s 40.08026ms

// Fourth Block dispatch - 3 seconds after the request. 4 Results.
18:16:28.502Z DEBUG WS BOT/test3.js: 6 End... 3s 53.779308ms
18:16:28.503Z DEBUG WS BOT/test3.js: 8 End... 3s 54.27472ms
18:16:28.504Z DEBUG WS BOT/test3.js: 9 End... 3s 55.358707ms
18:16:28.505Z DEBUG WS BOT/test3.js: 7 End... 3s 56.856392ms

// now you see each second with increasing results per second
18:16:29.519Z DEBUG WS BOT/test3.js: 13 End... 4s 69.557508ms
18:16:29.520Z DEBUG WS BOT/test3.js: 10 End... 4s 70.682548ms
18:16:29.520Z DEBUG WS BOT/test3.js: 14 End... 4s 70.377011ms
18:16:29.521Z DEBUG WS BOT/test3.js: 11 End... 4s 71.37652ms
18:16:29.535Z DEBUG WS BOT/test3.js: 12 End... 4s 85.550058ms
18:16:30.538Z DEBUG WS BOT/test3.js: 15 End... 5s 87.94975ms
18:16:30.539Z DEBUG WS BOT/test3.js: 16 End... 5s 88.68675ms
18:16:30.540Z DEBUG WS BOT/test3.js: 19 End... 5s 88.786227ms
18:16:30.540Z DEBUG WS BOT/test3.js: 17 End... 5s 90.013903ms
18:16:30.541Z DEBUG WS BOT/test3.js: 18 End... 5s 90.523922ms

Я упростил код и запросил 20 раз один и тот же запрос с таким же медленным ответом.

Это мой код: 

const MongoClient = require('mongodb').MongoClient;
const dbName = 'kd';
var db;

//Connect to Mongo first. Once connnected, send 20x the same aggregation.

MongoClient.connect(`mongodb://${config.mongo.user}:${config.mongo.password}@localhost:${config.mongo.port}/${config.mongo.dbname}?authSource=${config.mongo.authSource}`, { useNewUrlParser: true, poolSize: 10 })
.then((data) => {
  log.info("MONGO SUCCESFULLY CONNECTED!")
  db = data.db(dbName);
  for (var i = 0; i < 20; i++) {
  aggregation(i)
  }
})
.catch(e => { log.error(e)})

// aggregation which will be used (simplified)
function aggregation(i) {
  var hrstart = process.hrtime()
  log.debug(`${i} Start... %dms`)
    db.collection("s.log").aggregate([
    { $match: { "updated_at": { $gte: yesterday } } }, 
    { $sort: { updated_at: 1 } }, 
  ],
  function(err, cursor) {
    if (err) { log.error(err)}
    else {
      cursor.toArray(function(err,product) {
          hrend = process.hrtime(hrstart)
          log.debug(`${i} End... %ds %dms`, hrend[0], hrend[1] / 1000000)
       })
    }
  })
}

Я попытался увеличить poolSize, чтобы у драйвера было больше подключений, и он мог запускать их параллельно, но безуспешно. Использование Mongoose приводит к такой же низкой производительности.

Я также проверил mongostat, без чего-либо видимого, за исключением того, что соединения увеличиваются на одну в секунду 

    *0    *0     *0     *0       0    13|0  0.1% 3.4%       0 1.03G 40.0M 0|0 1|0  10.4k   73.4k    3 Mar 22 14:07:52.173
    *0    *0     *0     *0       0    12|0  0.1% 3.4%       0 1.03G 40.0M 0|0 1|0  6.72k   66.3k    3 Mar 22 14:07:53.201
    *0    *0     *0     *0       0    17|0  0.1% 3.4%       0 1.03G 40.0M 0|0 1|0  7.97k   68.5k    4 Mar 22 14:07:54.210
insert query update delete getmore command dirty used flushes vsize   res qrw arw net_in net_out conn                time
    *0    *0     *0     *0       0    18|0  0.1% 3.4%       0 1.03G 40.0M 0|0 1|0  8.62k   70.4k    5 Mar 22 14:07:55.198
    *0    *0     *0     *0       0    20|0  0.1% 3.4%       0 1.03G 40.0M 0|0 1|0  14.0k   74.5k    6 Mar 22 14:07:56.207
    *0    *0     *0     *0       0    20|0  0.1% 3.4%       0 1.04G 40.0M 0|0 1|0  9.23k   70.7k    7 Mar 22 14:07:57.198
    *0    *0     *0     *0       0    20|0  0.1% 3.4%       0 1.04G 40.0M 0|0 1|0  9.37k   69.7k    8 Mar 22 14:07:58.207
    *0    *0     *0     *0       0    22|0  0.1% 3.4%       0 1.04G 40.0M 0|0 1|0  10.0k   71.6k    9 Mar 22 14:07:59.198
    *0    *0     *0     *0       0    13|0  0.1% 3.4%       0 1.04G 41.0M 0|0 1|0  6.90k   67.6k   10 Mar 22 14:08:00.206
    *0    *0     *0     *0       0    14|0  0.1% 3.4%       0 1.04G 41.0M 0|0 1|0  7.07k   68.7k   10 Mar 22 14:08:01.203
    *0    *0     *0     *0       0    13|0  0.1% 3.4%       0 1.04G 41.0M 0|0 1|0  21.0k   84.8k   10 Mar 22 14:08:02.162
    *0    *0     *0     *0       0    11|0  0.1% 3.4%       0 1.04G 41.0M 0|0 1|0  1.36k   60.4k   10 Mar 22 14:08:03.200

Это журнал system.profile, который показывает, что каждый запрос выполняется за <1 мс. Здесь вы также можете увидеть задержку в 1 секунду до того, как mongod выполнит запрос и выполнит 1 операцию на соединение в секунду. </p> 

> db.system.profile.find({ns: "kdm.shop.log"}, {ts: 1, millis: 1}).sort({ ts: -1}).limit(20)
{ "millis" : 0, "ts" : ISODate("2019-03-22T18:16:30.538Z") }
{ "millis" : 0, "ts" : ISODate("2019-03-22T18:16:30.538Z") }
{ "millis" : 0, "ts" : ISODate("2019-03-22T18:16:30.537Z") }
{ "millis" : 0, "ts" : ISODate("2019-03-22T18:16:30.536Z") }
{ "millis" : 1, "ts" : ISODate("2019-03-22T18:16:30.535Z") }
{ "millis" : 0, "ts" : ISODate("2019-03-22T18:16:29.534Z") }
{ "millis" : 0, "ts" : ISODate("2019-03-22T18:16:29.519Z") }
{ "millis" : 0, "ts" : ISODate("2019-03-22T18:16:29.519Z") }
{ "millis" : 0, "ts" : ISODate("2019-03-22T18:16:29.518Z") }
{ "millis" : 0, "ts" : ISODate("2019-03-22T18:16:29.518Z") }
{ "millis" : 0, "ts" : ISODate("2019-03-22T18:16:28.504Z") }
{ "millis" : 0, "ts" : ISODate("2019-03-22T18:16:28.503Z") }
{ "millis" : 1, "ts" : ISODate("2019-03-22T18:16:28.502Z") }
{ "millis" : 1, "ts" : ISODate("2019-03-22T18:16:28.501Z") }
{ "millis" : 0, "ts" : ISODate("2019-03-22T18:16:27.488Z") }
{ "millis" : 0, "ts" : ISODate("2019-03-22T18:16:27.487Z") }
{ "millis" : 0, "ts" : ISODate("2019-03-22T18:16:27.486Z") }
{ "millis" : 1, "ts" : ISODate("2019-03-22T18:16:26.476Z") }
{ "millis" : 2, "ts" : ISODate("2019-03-22T18:16:26.474Z") }
{ "millis" : 0, "ts" : ISODate("2019-03-22T18:16:25.453Z") }

У кого-нибудь есть идея, почему она такая медленная и почему задержка отправки блока составляет 1 секунду? Кажется, что он увеличивает количество соединений каждую секунду на 1, но он выполняет только 1 операцию на соединение. Даже если он использует только одно соединение и выполняет одну операцию каждый раз, это должно быть намного быстрее - как показано на двух других моих системах!

Спасибо за вашу помощь. Если вам нужна дополнительная информация, дайте мне знать!

С уважением, Meffesino

...