Почему пухнет WAL каталог?

Question

[Владимир]

Конфигурация.
master - slave
При поступлении на мастер довольно большого объёма данных генерируется куча wal файлов и успешно уходят на slave.
при этом в какой-то момент времени slave перестаёт "проигрывать" wal и его каталог переполняется, следовательно slave падает.

Вроде как i\o высокие но при этом скорость ответа не растёт + CPU не находится в состоянии iowait. т.е на первы

Comments

[ky0]

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

[Владимир]

ky0 Запрос реально долгий.
правда, мастер его прожёвывает без проблем, а при раскатке этих wal на slave видимо затыкается в скорости (при этом система не сходит с ума и не говорит что она загружена).
мониторю расхождение wal на slave и master, и там видно, что файлы доезжают до копии, но они оч медленно проигрываются и начинают копится.

Answer 1

[Melkij]

Если реплика приостанавливает репликацию (видно по waiting в списке процессов для startup процесса) - значит ей мешают запущенные на ней транзакции. Проверьте свой max_standby_streaming_delay.

В целом почему база может не удалять WAL сверх необходимых:
- создан слот репликации но его не читают
- archive_command выполняется с ошибкой

Comments

[Владимир]

max_standby_streaming_delay = 30s на реплике нет подключений в этот момент. вообще.

слота репликации на слейве нет.

архивации тоже нет.

просто в какой-то момент будто перестают работать чекпоинты

[Melkij]

реплика перестаёт проигрывать wal != реплика делает restartpoint
Включите log_checkpoints и смотрите лог.

Реплика не обязана делать checkpoint по указанию мастера. Может делать по своему усмотрению от max_wal_size и checkpoint_timeout, но не может обновлять controlfile. Если у вас впритык места под wal и неравномерная по записи нагрузка - не делайте так или крутите на реплике чекпойнтер в более частую работу.

[Владимир]

Melkij, проблема в том что чекпоинтер настроен как на мастере. я как раз исходил из идеи что он будет отрабатывать самостоятельно по получению объёма данных или по истечению времени.
но (у меня нет лога вызова чекпоинта, но есть лог времени его отработки) так вот он вдруг перестаёт отрабатывать. и WAL бегут вверх.

wal там 200GB свободных, их точно не впритык.
не совсем понял что значит controlfile...

[Melkij]

checkpointer в списке процессов остаётся?
log_checkpoints можно включить на живую через sighup.

controlfile - важная штука, в которой как раз пишется когда был последний checkpoint и откуда надо стартовать базу. Его пишет только мастербаза, реплика может делать checkpoint, но не может обновлять controlfile. Поэтому даже если перед рестартом реплики сделать checkpoint на реплике (но не на мастере) - реплика будет стартовать с позиции последнего чекпойнта на мастере.

[Владимир]

Melkij, сегодня под нагрузкой ситуация повторилась.
но когда лог начинал расти постгря возвращала что-то в духе

2019-06-26 09:46:35 MSK < > %LOG: 00000: restartpoint starting: xlog
2019-06-26 09:46:35 MSK < > %LOCATION: LogCheckpointStart, xlog.c:8445
2019-06-26 09:51:25 MSK < > %LOG: 00000: restartpoint complete: wrote 670602 buffers (5.3%); 0 WAL file(s) added, 441 removed, 0 recycled; write=269.418 s, sync=0.421 s, total=289.467 s; sync files=199, longest=0.122 s, average=0.002 s; distance=4590361 kB, estimate=8031162 kB
2019-06-26 09:51:25 MSK < > %LOCATION: LogCheckpointEnd, xlog.c:8527
2019-06-26 09:51:25 MSK < > %LOG: 00000: recovery restart point at 1A44/924ACA48

тут понял что сам процесс восстановления
postgres: startup process recovering. работает относительно медленно. я так понимаю checkpoint должен вырезать все wal до pg_last_wal_replay_lsn
но что делать если сам процесс восстановления не справляется?

[Melkij]

я так понимаю checkpoint должен вырезать все wal до pg_last_wal_replay_lsn

нет, категоричное нет.
Нельзя удалять любые WAL за время с прошлого чекпойнта. (и за два чекпойнта если говорить о postgresql < 10.0)
Потому что так REDO recovery работает. Делается чекпойнт - то есть все изменённые блоки гарантированно скидываются на диск. При старте считаем что база в позиции последнего известного чекпойнта и накатываем все WAL записанные с того момента. При том, позицию для рестарта может писать только мастер.

pg_last_wal_replay_lsn - это где replay в этот момент. Никакого отношения к чекпойнтам не имеет. Вообще.

Если не справляется процесс восстановления startup - у вас отстаёт pg_last_xact_replay_timestamp и появляется заметная разница между pg_last_wal_receive_lsn и pg_last_wal_replay_lsn.
В этом случае смотреть надо на утилизацию дисков. На быстрых дисках можно упереться в CPU, startup однопоточный.

А checkpointer - это другой процесс. По большому счёту со startup не связанный.

2019-06-26 09:46:35 MSK < > %LOG: 00000: restartpoint starting: xlog
2019-06-26 09:51:25 MSK < > %LOG: 00000: restartpoint complete: wrote 670602 buffers (5.3%); 0 WAL file(s) added, 441 removed, 0 recycled; write=269.418 s, sync=0.421 s, total=289.467 s; sync files=199, longest=0.122 s, average=0.002 s; distance=4590361 kB, estimate=8031162 kB

4:50 работали (289.467), 7гб wal по итогам этого restartpoint удалено. Выглядит вполне.
Какой max_wal_size? Когда и чего сколько делают другие чекпойнты?

[Владимир]

Melkij,
max_wal_size = 20GB

4:50 работали

наверно это связанно с checkpoint_completion_target = 0.9 ?

Другие чекпоинты в начале нагрузки выглядят так же. а потом просто пропадают.

При этом загруженность растёт.

В виде графиков чекпоинты у меня видны вот так


я вообще имел ввиду что что файлы wal пропадают только после checkpoint, а он однозначно не может идти резать дальше последнего "проигранного" wal.
следовательно он не вычищает wal потому что startup процесс не успевает проиграть wal. но правда не понятно почему он прекращает выполняться каждые 5 минут.

+ ещё в отношении pg_stat_bgwriter
я вижу что
checkpoints_timed не инкрементируется
когда
checkpoints_req щёлкает вперёд, но записей в логе не появляется и wal меньше не становится.