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

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

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

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

Redis info

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

[simterm]

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

[/simterm]

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

[simterm]

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

[/simterm]

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

[simterm]

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       
...

[/simterm]

monitor:

[simterm]

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:{***}
...

[/simterm]

И slowlog:

[simterm]

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"

[/simterm]

См. также latency.

К ошибке.

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

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

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

[simterm]

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

[/simterm]

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

“Быстрофикс” – client-output-buffer-limit

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

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

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

[simterm]

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"

[/simterm]

Формат:

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 метров:

[simterm]

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"

[/simterm]

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

[simterm]

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

[/simterm]

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

[simterm]

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

[/simterm]

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

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

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

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

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

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

[simterm]

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
...

[/simterm]

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

[simterm]

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

[/simterm]

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

[simterm]

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

[/simterm]

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

[simterm]

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

[/simterm]

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

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

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

[simterm]

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

[/simterm]

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

[simterm]

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

[/simterm]

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

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

[simterm]

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.

[/simterm]

4.90 Gbits/sec – 625 MBytes/sec.

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

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

[simterm]

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
...

[/simterm]

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

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

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

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

[simterm]

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

[/simterm]

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

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

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

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