Redis: «psync scheduled to be closed ASAP for overcoming of output buffer limits» и client-output-buffer-limit

Автор: | 02/20/2020
 

Имеется Redis-кластер с Sentinel, см. Redis: репликация, часть 2 — Master-Slave репликация, и Redis Sentinel, Redis: fork — Cannot allocate memory, Linux, виртуальная память и vm.overcommit_memory и Redis: основные параметры конфигурации и тюнинг производительности.

Система работала отлично долгое время, пока мы не начали использовать кеш намного более активно.

Redis info

Проверить все ключи в базах можно так:

admin@bttrm-production-console:~$ redis-cli -h 10.0.3.105 -p 6389 INFO keyspace
Keyspace
db0:keys=5,expires=0,avg_ttl=0
db4:keys=16988,expires=2698,avg_ttl=30025662
db5:keys=138713,expires=90388,avg_ttl=7435947

А их размеры — с помощью bigkeys:

admin@bttrm-production-console:~$ redis-cli -h 10.0.3.105 -p 6389 -n 5 --bigkeys
...
[00.00%] Biggest string found so far 'projectname_aba3b5bf1af24246b465826658b3c375' with 45 bytes
...
[38.56%] Biggest string found so far 'projectname_44bb0e2dd7f4fabf41ee09001791bdc4' with 4627517 bytes
-------- summary -------
Sampled 150726 keys in the keyspace!
Total key length in bytes is 6782670 (avg len 45.00)
Biggest string found 'projectname_44bb0e2dd7f4fabf41ee09001791bdc4' has 4627517 bytes

Полезная опция --stat:

root@bttrm-production-console:/home/admin# redis-cli -h 10.0.3.105 -p 6389 --stat -i 2
------- data ------ --------------------- load -------------------- - child -
keys       mem      clients blocked requests            connections
10290781   3.80G    12      0       37279511 (+0)       79301
...
10292946   3.81G    10      0       37283233 (+701)     79502
...

monitor:

root@bttrm-production-console:/home/admin# redis-cli -h 10.0.3.105 -p 6389 monitor
...
1582037638.965389 [5 10.0.3.92:58594] "SET" "projectname_e7e0a3ed5251cb36e2925957981e9faa" "a:2:{***}
1582037638.967345 [5 10.0.3.71:40906] "SET" "projectname_80d9171937e4463d0238bcc42a54aead" "a:2:{***}
1582037638.967411 [5 10.0.3.71:40684] "SET" "projectname_e8b81cd503d87be74070aa012b22be4a" "a:2:{***}
...

И slowlog:

10.0.3.105:6389> SLOWLOG get 2
1) 1) (integer) 9
2) (integer) 1582119750
3) (integer) 21507206
4) 1) "FLUSHDB"
2) 1) (integer) 8
2) (integer) 1582058687
3) (integer) 71653
4) 1) "PSYNC"
2) "?"
3) "-1"

См. также latency.

К ошибке.

Ошибка «psync scheduled to be closed ASAP for overcoming of output buffer limits»

Прекрасным вечером система мониторинга сообщила о проблемах с кластером.

В логах это выглядело так:

2244:C 17 Feb 19:48:12.464 * DB saved on disk
2244:C 17 Feb 19:48:12.527 * RDB: 370 MB of memory used by copy-on-write
1911:M 17 Feb 19:48:12.681 * Background saving terminated with success
1911:M 17 Feb 19:48:12.681 * Starting BGSAVE for SYNC with target: disk
1911:M 17 Feb 19:48:12.744 * Background saving started by pid 2397
1911:M 17 Feb 19:48:13.251 * Slave 10.0.3.71:6389 asks for synchronization
1911:M 17 Feb 19:48:13.251 * Full resync requested by slave 10.0.3.71:6389
1911:M 17 Feb 19:48:13.251 * Waiting for end of BGSAVE for SYNC
1911:M 17 Feb 19:48:15.743 # Client id=3144 addr=10.0.3.92:40313 fd=104 name= age=31 idle=31 flags=S db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=11284 oll=1203 omem=269714472 events=r cmd=psync scheduled to be closed ASAP for overcoming of output buffer limits.
1911:M 17 Feb 19:48:15.743 # Client id=4300 addr=10.0.3.71:40029 fd=110 name= age=2 idle=2 flags=S db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=11284 oll=1203 omem=269714472 events=r cmd=psync scheduled to be closed ASAP for overcoming of output buffer limits.
1911:M 17 Feb 19:48:15.754 # Connection with slave 10.0.3.92:6389 lost.
1911:M 17 Feb 19:48:15.756 # Connection with slave 10.0.3.71:6389 lost.
1911:M 17 Feb 19:48:16.251 * Slave 10.0.3.71:6389 asks for synchronization
1911:M 17 Feb 19:48:16.251 * Full resync requested by slave 10.0.3.71:6389
1911:M 17 Feb 19:48:16.251 * Can't attach the slave to the current BGSAVE. Waiting for next BGSAVE for SYNC

Из всего этого текста нам важно сообщение «psync scheduled to be closed ASAP for overcoming of output buffer limits«.

«Быстрофикс» — client-output-buffer-limit

Решение — увеличить размер client-output-buffer-limit.

В двух словах — это размер буфера, используемого master-сервисом Redis для хранения данных, которые изменились в процессе синхронизации базы данных из памяти Redis-master и одного из его слейвов.

Проверяем значение сейчас:

root@bttrm-production-console:/home/admin# redis-cli -h 10.0.3.105 -p 6389
10.0.3.105:6389> config get client-output-buffer-limit
1) "client-output-buffer-limit"
2) "normal 0 0 0 slave 268435456 67108864 60 pubsub 33554432 8388608 60"

Формат:

client-output-buffer-limit <class> <hard limit> <soft limit> <soft seconds>

Дефолтные значения:

  • client-output-buffer-limit normal 0 0 0
  • client-output-buffer-limit slave 256mb 64mb 60
  • client-output-buffer-limit pubsub 32mb 8mb 60

С такими настройками соединение будет разорвано немедленно при достижении <hard limit> — 256 МБ, либо если <soft limit> — 64 МБ — превышен дольше лимита из <soft seconds> — 60 секунд.

Нас интересует slave 268435456 67108864 60.

На Мастере увеличиваем лимит буфера до 512 метров:

10.0.3.105:6389> config set client-output-buffer-limit "slave 4194990176 4194990176 0"
OK
10.0.3.105:6389> config get client-output-buffer-limit
1) "client-output-buffer-limit"
2) "normal 0 0 0 slave 4194990176 4194990176 0 pubsub 33554432 8388608 60"

Мне пришлось увеличивать буфер с 512 мегабайт до 1 гига, потом 2, 4 ,8 — и только на 10 GB синхронизация прошла успешно, при том, что база в памяти была чуть меньше 5 гигабайт:

1911:M 17 Feb 20:30:21.308 * Slave 10.0.3.71:6389 asks for synchronization
1911:M 17 Feb 20:30:21.308 * Full resync requested by slave 10.0.3.71:6389
1911:M 17 Feb 20:30:21.308 * Starting BGSAVE for SYNC with target: disk
1911:M 17 Feb 20:30:21.389 * Background saving started by pid 8166
1911:M 17 Feb 20:30:21.851 * Slave 10.0.3.92:6389 asks for synchronization
1911:M 17 Feb 20:30:21.851 * Full resync requested by slave 10.0.3.92:6389
1911:M 17 Feb 20:30:21.851 * Waiting for end of BGSAVE for SYNC
8166:C 17 Feb 20:30:55.069 * DB saved on disk
8166:C 17 Feb 20:30:55.148 * RDB: 851 MB of memory used by copy-on-write
1911:M 17 Feb 20:30:55.365 * Background saving terminated with success
1911:M 17 Feb 20:31:05.160 * Synchronization with slave 10.0.3.92:6389 succeeded
1911:M 17 Feb 20:31:05.223 * Synchronization with slave 10.0.3.71:6389 succeeded

И в логах слейва:

11347:S 17 Feb 20:29:06.523 * Connecting to MASTER 10.0.3.105:6389
11347:S 17 Feb 20:29:06.524 * MASTER <-> SLAVE sync started
11347:S 17 Feb 20:29:06.526 * Non blocking connect for SYNC fired the event.
11347:S 17 Feb 20:29:06.530 * Master replied to PING, replication can continue...
11347:S 17 Feb 20:29:06.532 * Partial resynchronization not possible (no cached master)
11347:S 17 Feb 20:29:06.612 * Full resync from master: e96dc8dcea06375e45f9e0796f796cb642b2a94a:243379789779
11347:S 17 Feb 20:29:36.120 * MASTER <-> SLAVE sync: receiving 1457381394 bytes from master
11347:S 17 Feb 20:29:43.069 # I/O error trying to sync with MASTER: connection lost
11347:S 17 Feb 20:29:43.191 * Connecting to MASTER 10.0.3.105:6389
11347:S 17 Feb 20:29:43.191 * MASTER <-> SLAVE sync started
11347:S 17 Feb 20:29:43.198 * Non blocking connect for SYNC fired the event.
11347:S 17 Feb 20:29:43.446 * Master replied to PING, replication can continue...
11347:S 17 Feb 20:29:43.450 * Partial resynchronization not possible (no cached master)
11347:S 17 Feb 20:29:43.532 * Full resync from master: e96dc8dcea06375e45f9e0796f796cb642b2a94a:247290941137
11347:S 17 Feb 20:30:17.763 * MASTER <-> SLAVE sync: receiving 1458314307 bytes from master
11347:S 17 Feb 20:30:20.516 # I/O error trying to sync with MASTER: connection lost
11347:S 17 Feb 20:30:21.303 * Connecting to MASTER 10.0.3.105:6389
11347:S 17 Feb 20:30:21.303 * MASTER <-> SLAVE sync started
11347:S 17 Feb 20:30:21.304 * Non blocking connect for SYNC fired the event.
11347:S 17 Feb 20:30:21.305 * Master replied to PING, replication can continue...
11347:S 17 Feb 20:30:21.307 * Partial resynchronization not possible (no cached master)
11347:S 17 Feb 20:30:21.389 * Full resync from master: e96dc8dcea06375e45f9e0796f796cb642b2a94a:251282993972
11347:S 17 Feb 20:30:55.365 * MASTER <-> SLAVE sync: receiving 1459112192 bytes from master
11347:S 17 Feb 20:31:05.299 * MASTER <-> SLAVE sync: Flushing old data
11347:S 17 Feb 20:31:20.802 * MASTER <-> SLAVE sync: Loading DB in memory
11347:S 17 Feb 20:31:41.073 * MASTER <-> SLAVE sync: Finished with success

А теперь, когда Production снова жив, рассмотрим внимательнее.

Что вообще происходит?

Redis master-slave — процесс синхронизации

Кратко вспомним процесс синхронизации мастер-слейв:

  1. слейв при запуске или после потери коннекта обращается к мастеру с просьбой передать на слейв данные из базы мастера, что бы слейв мог начать обслуживать запросы клиентов
  2. мастер в ответ на этот запрос:
    1. создаёт дочерний процесс, который дампит базу Redis из памяти на диск в файл dump.rdb (см. fork() vs fork() vs clone())
    2. в это время мастер продолжает отвечать на запросы от других клиентов
    3. и любые данные, которые изменились этими клиентами с момента начала создания дампа сохраняет в буфер репликации
  3. мастер сообщает слейву, что дамп готов, и слейв начинает загружать его по сети к себе, сохраняя на диск
  4. слейв завершает передачу дампа к себе, загружает в память своего процесса Redis, и сообщает мастеру, что слейв готов к работе
  5. мастер проверят свой буфер, и если в нём есть данные — он передаёт изх на слейв, что бы тот заменил данные в своей базе, созданной из дампа, последними, актуальными данными
  6. слейв применяет изменения, и вступает в работу

Таким образом, синхронизация мастер-слейв включает в себя два этапа:

  1. сначала содаётся полная копия данных, которая может содержать устаревшие данные
  2. затем выполняется последовательный набор апдейтов из буфера, которые заканчвают приведение новой базы в состояние, аналогичное базе на мастере

Размер базы и буфера

Проблемы — при снапшоте может потребоваться памяти до х3 от размера базы, и главная сложность заключается даже не в том, что бы создать сам снапшот данных, а в том, что его надо передать на слейв, и при этом сохранить консистентность данных между мастером и слейвом, так как пока данные передаются по сети, с её задержками, пока слейв запишет её к себе на диск, пока загрузит к себе в память — на мастере данные успеют измениться.

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

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

В любом случае, тут всё достаточно условно, и требует тестирования и мониторинга для подбора оптимальных настроек.

Приблизительынй пример расчёта.

Проверяем празмер базы в памяти:

root@bttrm-production-console:/home/admin# redis-cli -h 10.0.3.105 -p 6389 info memory
Memory
used_memory:871106648
used_memory_human:830.75M
...

Создаём дамп:

root@bttrm-production-console:/home/admin# redis-cli -h 10.0.3.105 -p 6389 bgsave
Background saving started

Проверяем размер файла RBD:

root@bttrm-production-console:/home/admin# ls -lh /var/lib/redis-cluster/dump.rdb
-rw-rw---- 1 redis redis 345M Feb 20 15:04 /var/lib/redis-cluster/dump.rdb

Сейчас база в памяти всего 830 мб, но вообще у нас лимит задан в % от общей памяти машины:

root@bttrm-production-console:/home/admin# cat /etc/redis-cluster/redis-cluster.conf  | grep maxmem
maxmemory 50%
maxmemory-policy allkeys-lru

Т.е. в принципе база может расти до ~16 ГБ (у сервера 32 GB), после создания дампа — он будет 7-8 гиг.

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

Для проверки скорости используем iperf — устанавливаем на Мастер и Слейв хостах:

root@bttrm-production-console:/home/admin# apt -y install iperf3

Находим IP мастера, и на нём запускаем iperf в режиме сервера:

root@bttrm-production-console:/home/admin# iperf3 -s
-----------------------------------------------------------
Server listening on 5201
-----------------------------------------------------------
...

Позже наткнулся на redis-cli --latency -h <Redis IP> -p <Redis port>

С хоста Слейва запускаем тест:

root@bttrm-production-app-1:/home/admin# iperf3 -c 10.0.3.105
Connecting to host 10.0.3.105, port 5201
[  4] local 10.0.3.71 port 47046 connected to 10.0.3.105 port 5201
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-1.00   sec   585 MBytes  4.90 Gbits/sec    0   1.37 MBytes
...
[  4]   9.00-10.00  sec   592 MBytes  4.97 Gbits/sec    0   2.06 MBytes
- - - - - - - - - - - - - - - - - - - - - - - - -
[ ID] Interval           Transfer     Bandwidth       Retr
[  4]   0.00-10.00  sec  5.78 GBytes  4.96 Gbits/sec    0             sender
[  4]   0.00-10.00  sec  5.78 GBytes  4.96 Gbits/sec                  receiver
iperf Done.

4.90 Gbits/sec — 625 MBytes/sec.

Учитывая, что максимальный размер дампа у нас будет 7 GB, и используем калькулятор тут>>> — получаем 13 секунд.

А теперь используя --stat можно проверить — как много ключей добавляется за 1 секунду:

root@bttrm-production-app-1:/home/admin# redis-cli -h 10.0.3.105 -p 6389 --stat
------- data ------ --------------------- load -------------------- - child -
keys       mem      clients blocked requests            connections
530178     765.42M  9       0       91699673 (+0)       2856563
530407     766.04M  16      0       91700194 (+521)     2856580
...

530178 — 530407 == 229 ключей за секунду.

Либо можно использовать Prometheus и redis-exporter, а затем сделать выборку по SET-запросам, т.к. основной массив данных будет в них, используя запрос вида:

irate(redis_commands_total{instance="production.bttrm-production-console",job="redis-exporter-cluster",cmd="set"}[1m])

И размеры ключей:

root@bttrm-production-app-1:/home/admin# redis-cli -h 10.0.3.105 -p 6389 --bigkeys
...
[00.00%] Biggest string found so far 'projectname_8caf094272eac1c6a51213c1c878767b' with 45 bytes
...
[00.00%] Biggest string found so far 'projectname_44bb0e2dd7f4fabf41ee09001791bdc4' with 4626843 bytes
...
Biggest string found 'projectname_44bb0e2dd7f4fabf41ee09001791bdc4' has 4626843 bytes

229 ключей по 4.5 MB == 1 GB.

Но — такой вариант расчёта ОЧЕНЬ приблизительный, т.к. считаем ключи в обычном режиме работы.

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

Ссылки по теме