Почему каждые несколько минут активность на local.oplog.rs блокирует клиентов mongo

Проблема:

Каждые одну или две минуты клиенты монго останавливаются примерно на 3 секунды. Нормальное время работы для обновлений составляет около 1 или 2 миллисекунды. Когда появится эта медлительность, у нас есть куча обновлений продолжительностью от 1 до 3 секунд.

Журнал медленных запросов не показывает ничего, что связано с этим. Также не выполняется отладка клиента mongo (mongo-php-client).

Текущая архитектура имеет 1 мастер, 1 ведомый и один арбитр в наборе реплик.

Выполненные запросы всегда одинаковы (upsert by _id, insert with new MongoId). Нет "каждые несколько минут, когда мы запускаем это супердорожное обновление"

Блокировка, по-видимому, вызвана local.oplog.rs. По крайней мере, это то, что показывает вывод mongotop ниже. Я не нашел никаких указаний на то, что вторичная проблема вызывает эту проблему, так как выходы всех следующих команд кажутся стабильными. Я не нашел никакой информации, указывающей, что медленность вызвана конкретным запросом.

Идея того, как мы храним данные, - это предварительно агрегированные отчеты. У нас много обновлений (пара сотен в секунду), но очень низкий уровень запросов. Индексы привязаны к дате (кроме _id, который вычисляется из составного ключа на основе всех измерений, содержащихся в записи. В отличие от этого, я имею в виду, что _id не является инкрементным, как это было бы с индексом ObjectId). Чтобы дать представление, индексы в самой большой коллекции (в Mb):

"indexSizes" : {
    "_id_" : 1967,
    "owner_date" : 230,
    "flow_date" : 231,
    "date" : 170
},

Большинство других коллекций имеют индексы размером 100 МБ или меньше. Во всех коллекциях индекс _id является самым большим. Стоит отметить, что эти идентификаторы создаются вручную (на основе метаданных, поэтому вставка выполняется как upsert и не является инкрементной)

Followup:

Edit1: После более глубокой обработки, кажется, что блокировка связана с процессом rsync журнала, когда он сбрасывается на диск. Журнал находится в той же файловой системе, что и файлы данных, но медленность не ожидается, поскольку диски являются быстрыми ssd-устройствами.

Edit2: После некоторых тестов способность записи дисков не является проблемой. Обычно мы пишем со скоростью несколько мегабайт в секунду. Выполняя некоторые тесты на диске, он без проблем принимает 150 МБ/с.

Ожидаемый ответ:

Почему происходит это время простоя?

  • Указатели на возможные причины для дальнейшего изучения
  • Опыт/решение на основе подобных случаев

Проблема Объяснение:

Следующие команды запускаются в основном node

Каждый раз, когда появляется медлительность, мы видим следующее в монгостате (два примера)

insert query update delete getmore command % dirty % used flushes vsize  res qr|qw ar|aw netIn netOut conn set repl     time
    10    *0    141     *0      93   120|0     0.4   80.0       0 11.5G 9.4G   0|1   1|0  110k    71k  274 rs0  PRI 13:15:44
    12    *0    178     *0      72   105|0     0.2   80.0       1 11.5G 9.4G   0|0   1|0  111k    79k  274 rs0  PRI 13:15:45
    47    *0      7     *0       0   159|0     0.1   80.0       0 11.5G 9.4G   0|0   2|1   15k    44k  274 rs0  PRI 13:15:49 !!!!HERE
    14    *0    929     *0      99   170|0     0.2   80.0       0 11.5G 9.4G   0|0   1|0  419k   417k  274 rs0  PRI 13:15:50
    21    *0    287     *0     124   181|0     0.2   80.0       0 11.5G 9.4G   0|0   1|0  187k   122k  274 rs0  PRI 13:15:51

insert query update delete getmore command % dirty % used flushes vsize  res qr|qw ar|aw netIn netOut conn set repl     time
    10    *0    145     *0      70   108|0     0.3   79.9       0 11.5G 9.4G   0|0   1|0   98k    71k  274 rs0  PRI 13:16:48
    11    *0    155     *0      72   111|0     0.2   79.9       1 11.5G 9.4G   0|0   1|0  103k    75k  274 rs0  PRI 13:16:49
    44    *0      3     *0       0   144|0     0.0   79.9       0 11.5G 9.4G   0|2   1|0   11k    75k  274 rs0  PRI 13:16:53 !!!!HERE
    11    *0    837     *0      94   134|0     0.2   79.9       0 11.5G 9.4G   0|0   1|0  377k   348k  274 rs0  PRI 13:16:54
    12    *0    180     *0      86   139|0     0.2   79.9       0 11.5G 9.4G   0|0   1|0  122k    85k  274 rs0  PRI 13:16:55
    14    *0    195     *0      83   124|0     0.2   79.9       0 11.5G 9.4G   0|0   2|0  125k    89k  274 rs0  PRI 13:16:56

в столбце обновления есть сокращение и следующее много больше обновлений. Заметим также, что мы используем мангостат с задержкой в ​​1 секунду. Когда появляется медленность, монгостат перестает отвечать на несколько секунд. Стоп присутствует только в главном, а не на подчиненном сервере.

Это результат работы mongotop при возникновении этой проблемы (в 2015-07-07T13: 29: 38):

(пример с немного более контекстом можно найти здесь)

                                                                                        ns    total     read    write    2015-07-07T13:29:33+02:00
                                                           database_name.d_date_flow_owner    555ms    550ms      4ms                             
                                                                            local.oplog.rs     61ms     53ms      7ms                             
                                                      database_name.client_context_bbbbbbb     15ms      0ms     15ms                             
                                                        database_name.d_date_landing_owner     15ms      0ms     15ms                             
                                                        database_name.d_date_billing_owner     10ms      0ms     10ms                             
database_name.w_bl_carrier_country_date_device_flow_landing_manager_op1_os_owner_prod_site      7ms      0ms      7ms                             
                database_name.d_carrier_country_date_device_flow_landing_op1_os_owner_site      5ms      0ms      5ms                             
                                                        database_name.d_country_date_owner      5ms      0ms      5ms                             
                                                         database_name.d_date_device_owner      5ms      0ms      5ms                             
                                                             database_name.d_date_os_owner      5ms      0ms      5ms                             

                                          ns    total    read    write    2015-07-07T13:29:37+02:00
        database_name.client_context_bbbbbbb      2ms     0ms      2ms                             
      database_name.client_context_aaaaaaaaa      1ms     0ms      1ms                             
                   admin.system.backup_users      0ms     0ms      0ms                             
                     admin.system.namespaces      0ms     0ms      0ms                             
                      admin.system.new_users      0ms     0ms      0ms                             
                        admin.system.profile      0ms     0ms      0ms                             
                          admin.system.roles      0ms     0ms      0ms                             
                          admin.system.users      0ms     0ms      0ms                             
                        admin.system.version      0ms     0ms      0ms                             
                               database_name      0ms     0ms      0ms                             

                                                                        ns     total      read     write    2015-07-07T13:29:38+02:00
                                                            local.oplog.rs    8171ms    4470ms    3701ms                             
                                            database_name.d_date_op1_owner      45ms       0ms      45ms                             
                                         database_name.d_date_device_owner      39ms       0ms      39ms                             
                                                database_name.m_date_owner      34ms       0ms      34ms                             
                                                database_name.d_date_owner      32ms       0ms      32ms                             
                                           database_name.d_date_owner_site      31ms       0ms      31ms                             
                                        database_name.d_carrier_date_owner      30ms       0ms      30ms                             
                                           database_name.d_date_flow_owner      30ms       0ms      30ms                             
                                        database_name.d_date_owner_product      28ms       0ms      28ms                             
database_name.d_carrier_country_date_device_flow_landing_op1_os_owner_site      27ms       0ms      27ms                             

                                                                                        ns    total     read    write    2015-07-07T13:29:39+02:00
                                                           database_name.d_date_flow_owner    558ms    552ms      6ms                             
                                                                            local.oplog.rs     62ms     61ms      1ms                             
                                                        database_name.d_carrier_date_owner     17ms      0ms     17ms                             
                                                                database_name.d_date_owner     16ms      0ms     16ms                             
database_name.w_bl_carrier_country_date_device_flow_landing_manager_op1_os_owner_prod_site      7ms      0ms      7ms                             
                                                        database_name.d_date_billing_owner      6ms      0ms      6ms                             
                database_name.d_carrier_country_date_device_flow_landing_op1_os_owner_site      5ms      0ms      5ms                             
                                                        database_name.d_country_date_owner      5ms      0ms      5ms                             
                                                         database_name.d_date_device_owner      5ms      0ms      5ms                             
                                                            database_name.d_date_op1_owner      5ms      0ms      5ms                             

Отладка клиента php mongo, который показывает проблему (последние две строки отладки PhpMongoClient):

(пример с чуть более контекстом можно найти здесь)

Update duration: 2ms
Update duration: 1ms
Update duration: 1ms
Update duration: 4006ms
    PhpMongoClient debug: 2015-07-07 10:40:26 -  PARSE (INFO): Parsing mongodb://primary_host.lan,secondary_host.lan
    PhpMongoClient debug: 2015-07-07 10:40:26 -  PARSE (INFO): - Found node: primary_host.lan:27017
    [....]
    PhpMongoClient debug: 2015-07-07 10:40:26 -  REPLSET (FINE): limiting by credentials: done
    PhpMongoClient debug: 2015-07-07 10:40:26 -  REPLSET (FINE): sorting servers by priority and ping time
    PhpMongoClient debug: 2015-07-07 10:40:26 -  REPLSET (FINE): - connection: type: PRIMARY, socket: 42, ping: 0, hash: primary_host.lan:27017;rs0;database_name/user/5ca571e7db198eeee3abee35857bfd53;30751
    PhpMongoClient debug: 2015-07-07 10:40:26 -  REPLSET (FINE): sorting servers: done
    PhpMongoClient debug: 2015-07-07 10:40:26 -  REPLSET (FINE): selecting near servers
    PhpMongoClient debug: 2015-07-07 10:40:26 -  REPLSET (FINE): selecting near servers: nearest is 0ms
    PhpMongoClient debug: 2015-07-07 10:40:26 -  REPLSET (FINE): - connection: type: PRIMARY, socket: 42, ping: 0, hash: primary_host.lan:27017;rs0;database_name/user/5ca571e7db198eeee3abee35857bfd53;30751
    PhpMongoClient debug: 2015-07-07 10:40:26 -  REPLSET (FINE): selecting near server: done
    PhpMongoClient debug: 2015-07-07 10:40:26 -  REPLSET (INFO): pick server: random element 0
    PhpMongoClient debug: 2015-07-07 10:40:26 -  REPLSET (INFO): - connection: type: PRIMARY, socket: 42, ping: 0, hash: primary_host.lan:27017;rs0;database_name/user/5ca571e7db198eeee3abee35857bfd53;30751
    PhpMongoClient debug: 2015-07-07 10:40:26 -  CON (FINE): No timeout changes for primary_host.lan:27017;rs0;database_name/user/5ca571e7db198eeee3abee35857bfd53;30751
    PhpMongoClient debug: 2015-07-07 10:40:30 -  CON (FINE): No timeout changes for primary_host.lan:27017;rs0;database_name/user/5ca571e7db198eeee3abee35857bfd53;30751
Update duration: 3943ms
Update duration: 3476ms
Update duration: 2008ms
Update duration: 961ms
Update duration: 956ms
Update duration: 20ms
Update duration: 20ms
Update duration: 3ms
Update duration: 42ms
Update duration: 24ms
Update duration: 25ms
Update duration: 56ms
Update duration: 24ms
Update duration: 11ms
Update duration: 11ms
Update duration: 3ms
Update duration: 2ms
Update duration: 3ms
Update duration: 1ms
Update duration: 1ms
Update duration: 1ms
Update duration: 2ms

Mongo Информация:

  • Монго Версия: 3.0.3
  • Набор реплик с 1 подчиненным и 1 арбитром
  • Задержка репликации зависит от 0 до 4 секунд.
  • Двигатель: WiredTiger
  • Файловая система: XFS
  • Оперативная система: выпуск Red Hat Enterprise Linux Server 7.1
  • Память: 24 Гб. Сообщается htop как 40%, 60% кеш

Ответы

Ответ 1

Эта проблема теперь исчезла. Было предпринято два действия:

  • Переработал систему с предварительными агрегатами. Рабочая нагрузка монго уменьшилась в 10 раз.
  • Обновленная версия mongo to 3.0.6

К сожалению, эти два изменения были переведены в онлайн с большим количеством времени между ними. У меня есть подозрение, что сокращение рабочей нагрузки сделало трюк (который может или не может быть связан с проблемой, о которой @steve-brisk указал) по крайней мере на данный момент (мы увидим, когда мы снова удалим предыдущие уровни рабочей нагрузки). Но, поскольку версия также обновляется, возможно, что даже с предыдущими уровнями рабочей нагрузки мы могли бы не столкнуться с этой проблемой еще раз.

У меня нет доказательств, указывающих на одно из двух решений. Но после взятия обоих из них проблема решена.