Почему каждые несколько минут активность на 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 указал) по крайней мере на данный момент (мы увидим, когда мы снова удалим предыдущие уровни рабочей нагрузки). Но, поскольку версия также обновляется, возможно, что даже с предыдущими уровнями рабочей нагрузки мы могли бы не столкнуться с этой проблемой еще раз.
У меня нет доказательств, указывающих на одно из двух решений. Но после взятия обоих из них проблема решена.