Поиск причин замедленной работы redis на виртуальной машине

По специфике работы нам часто приходится иметь дело с самыми разными конфигурациями серверной инфраструктуры клиентов. Сегодня хотел бы поделиться моим опытом поиска первопричины сбоев в работе редис-кластера, которая вылилась в большие временные затраты, но могла быть решена намного быстрее. Возможно, мой опыт сэкономит время кому-то из начинающих администраторов при решении подобных задач.

Постановка задачи

Имеется 3 сервера в локальной сети со следующим набором ресурсов:

• 8 CPU Intel® Xeon® E3-1270 v5 @ 3.60GHz
• 64 GB DDR3 RAM 1600MHz
• SSD 447 GB с разделом /var/lib/redis

На каждом из них (два физических сервера и одна виртуальная машина) расположены по 2 инстанса redis, мастер и реплика. Запросы на чтение могут обрабатываться любым из инстансов, запись – только мастером. Графическое представление конфигурации привожу ниже:



При работе по одной из задач было замечено некорректное инфраструктурное распределение инстансов redis по серверам:



Замечено, что одна из пар мастер-реплика поменялись местами. Чтобы восстановить заданный порядок, сделали ручной failover, привели кластер к исходному виду.

И все бы было хорошо, если бы каждый день после запуска крона в час ночи мастер на сервере 10.0.0.3 не превращался в тыкву снова не перезжал на сервер 10.0.0.1.

Лог мастера:

# Connection with slave client id #123 lost.
# Failover auth denied to 10.0.0.1:6382 its master is up
# Configuration change detected. Reconfiguring myself as a replica of  10.0.0.1:6382

Лог реплики:

FAIL message received from 10.0.0.2:6381 about 10.0.0.3:6381
# Cluster state changed: fail
# Failover auth granted to 10.0.0.1:6382 for epoch 799
# Cluster state changed: ok
Clear FAIL state for node 10.0.0.3:6381: master without slots is reachable again.
Marking node 10.0.0.3:6381 as failing (quorum reached).
Clear FAIL state for node 10.0.0.3:6381: slave is reachable again.

Так, при запуске крона происходит запись данных в мастер, он становится недоступен и кворум его выгоняет, после чего он снова появляется на радарах, но присоединяется к кластеру в роли реплики.

Причем восстановление порядка в кластере проходит успешно, до следующего запуска крона мастер работает как мастер.

Нужно ли решать эту проблему?

При переезде мастера, описанного выше, два мастера оказываются на одном сервере. При выключении этого сервера восстановление кластера может происходить продолжительное время (от 15 минут). Вот такая отказонеустойчивость у отказоустойчивой конфигурации.

Возможно, чтобы решить проблему, стоит поднять величину таймаута в кластере? Чтобы выполнение крона занимало меньше времени, чем таймаут, тогда сервер вновь начнет отвечать на запросы из кворума и описанный выше сценарий нарушения порядка в кластере не сработает.

В ходе тестов таймаут был увеличен с 5 до 10 секунд, но это не помогло, крон-задача занимает машину на большее время. Еще больше поднимать таймаут? В этом случае мы просто снижаем отказоустойчивость, поскольку время реакции кластера на действительно серьезную проблему может растянуться.

Поиск причины нарушения конфигурации кластера.

Почему крон-задача, выполняемая на всех серверах, при одинаковой конфигурации занимает много времени на одном сервере и не создает никаких ощутимых проблем на других? Каждый раз при смене порядка мастеров и реплик смена происходила только у одной пары мастер-реплика.

• Ресурсы? Может быть у сервера 10.0.0.3 худшими ресурсами, чем остальные? Нет. Конфигурация серверов идентична, виртуальный сервер имеет на 10% меньше оперативной памяти, но она не используется полностью.
• Сетевые проблемы? Возможно, есть сетевые проблемы между серверами? Нет, здесь никаких вопросов, между всеми серверами показатели одинаковые.

# iperf -c 10.0.0.3
------------------------------------------------------------
Client connecting to 10.0.0.3, TCP port 5001
TCP window size: 85.0 KByte (default)
------------------------------------------------------------
[  3] local 10.0.0.2 port 47646 connected with 10.0.0.3 port 5001
[ ID] Interval       Transfer     Bandwidth
[  3]  0.0-10.0 sec  1.10 GBytes   946 Mbits/sec

• Проблема с дисками? Возможно запись или чтение занимает больше времени? Чтение на сервере 10.0.0.3 действительно замедлено:

Server-s1# hdparm -Tt /dev/sda
/dev/sda:
 Timing cached reads:   33894 MB in  2.00 seconds = 16967.92 MB/sec
 Timing buffered disk reads: 538 MB in  3.00 seconds = 179.22 MB/sec

Server-v3# hdparm -Tt /dev/xvda5
 /dev/xvda5:
 Timing cached reads:   7352 MB in  1.99 seconds = 3700.67 MB/sec
 Timing buffered disk reads: 186 MB in  3.00 seconds =  61.98 MB/sec

Скорость записи отличается незначительно:

Server-s1# sync; dd if=/dev/zero of=/var/lib/redis/tempfile bs=1M count=5024; sync
5024+0 записей получено
5024+0 записей отправлено
 скопировано 5268045824 байта (5,3 GB), 9,31237 c, 566 MB/c

Server-v3# sync; dd if=/dev/zero of=/var/lib/redis/tempfile bs=1M count=5024; sync
5024+0 записей получено
5024+0 записей отправлено
 скопировано 5268045824 байта (5,3 GB), 12,0484 c, 437 MB/c

На этом моменте идеи кончились. Результаты redis-benchmark явно показывают, что на сервере 10.0.0.3 redis просто работает в 8-10 раз медленнее по всем показателям.

Redis-benchmark на физической машине:

# redis-benchmark -h 10.0.0.2 -p 6381 -q
PING_INLINE: 223214.28 requests per second
PING_BULK: 237529.69 requests per second
SET: 222717.16 requests per second
GET: 237529.69 requests per second
INCR: 227272.73 requests per second
LPUSH: 213219.61 requests per second
LPOP: 241545.89 requests per second
SADD: 234741.78 requests per second
SPOP: 225225.22 requests per second
LPUSH (needed to benchmark LRANGE): 218340.61 requests per second
LRANGE_100 (first 100 elements): 242718.45 requests per second
LRANGE_300 (first 300 elements): 242718.45 requests per second
LRANGE_500 (first 450 elements): 230414.75 requests per second
LRANGE_600 (first 600 elements): 222222.23 requests per second
MSET (10 keys): 177304.97 requests per second

Redis-benchmark на виртуальной машине:

# redis-benchmark -h 10.0.0.3 -p 6381 -q
PING_INLINE: 25542.79 requests per second
PING_BULK: 27434.84 requests per second
SET: 30797.66 requests per second
GET: 26673.78 requests per second
INCR: 31113.88 requests per second
LPUSH: 32133.68 requests per second
LPOP: 32331.07 requests per second
SADD: 29594.55 requests per second
SPOP: 30826.14 requests per second
LPUSH (needed to benchmark LRANGE): 30988.54 requests per second
LRANGE_100 (first 100 elements): 26413.10 requests per second
LRANGE_300 (first 300 elements): 27100.27 requests per second
LRANGE_500 (first 450 elements): 22706.63 requests per second
LRANGE_600 (first 600 elements): 29429.08 requests per second
MSET (10 keys): 23468.67 requests per second

Хорошо, может быть ухудшение дают уменьшенная скорость чтения, которая была определена выше. Но в 10 ли раз?

В этот момент все ссылки на первых страницах в гугле уже проверены по несколько раз. Вдруг, на странице ObjectRocket встретил упоминание, что в этом может быть виноват гипервизор и житейский совет, не ставить redis на виртуалки под управлением Xen:

Probably the two most common operational choices which cause Redis to slow down is to 1) put it on a virtual machine – especially a Xen hypervisor based one and 2) heavy disk persistence.

Так, а какой у нас гипервизор на виртуальной машине?

# virt-what
xen
xen-hvm

И только здесь я открыл страничку документации, где по полочкам разложено, что для работы redis использует операцию fork

Latency generated by fork
In order to generate the RDB file in background, or to rewrite the Append Only File if AOF persistence is enabled, Redis has to fork background processes. The fork operation (running in the main thread) can induce latency by itself.

А развязка истории в том, что под управлением Xen эта операция замедляется:

Fork time in different systems
Modern hardware is pretty fast at copying the page table, but Xen is not. The problem with Xen is not virtualization-specific, but Xen-specific.

Разработчики даже указали как быть пользователям Amazon, какие именно инстансы можно использовать для того чтобы этой проблемы не возникало.

For EC2 users, make sure you use HVM based modern EC2 instances, like m3.medium. Otherwise fork() is too slow.

Итого

При анализе проблемы, которая была выявлено случайно, пришлось пройти довольно длинный путь. Тезисно обозначу этапы, которые пришлось пройти при решении данной задачи:

• Подтверждение факта повторения описанной проблемы каждые сутки
• Проверка необходимости детально разобраться в причинах
• Анализ банка близких задач по проекту, куда было затрачено много времени, но решение не обнаружилось.
• Сравнение доступных и используемых ресурсов на трех машинах
• Исключение сетевых проблем
• Проверка состояния дисков и скорости работы
• Анализ данных redis-benchmark
• Огромный по количеству затрат этап поиска причин этой и подобных проблем в открытых источниках
• Подробное изучение документации

Выводы

Причин, влияющих на скорость работы сервера может быть немало, при их поиске не забывайте в первую очередь проверять официальную документацию, особенно если она качественно написана. Возможно там не только уже в подробностях описана ваша проблема, но и представлены варианты ее решения.

P.S.: Также мы делимся своим опытом в DevOps здесь: telegram-канал DevOps FM