Восстановление после kill -9 в PostgreSQL: pg_control, redo и сколько это длится

После kill -9 PostgreSQL 18 поднялся за 1,6 секунды: записал в лог «not properly shut down», проиграл 329,7 МиБ журнала за 1,10 с и открылся. Откуда он знал, с какого места читать, и почему ни одна из 4 клиентских транзакций, оборванных на середине, не оставила следа? Старт берёт из pg_control адрес REDO последней контрольной точки и повторяет все записи WAL до конца журнала, ничего не откатывая. InnoDB делает то же и дополнительно откатывает незавершённые транзакции по undo, SQLite возвращает страницы из журнала отката. Расположение pg_control описано в статье про каталог данных.

DBA / 01koddo

От checkpoint до открытия: что делает старт после аварии

Стенд

Контрольные точки на время нагрузки откладываем: checkpoint_timeout = 15min, max_wal_size = 16GB, иначе точка сократит путь redo. Остальное по умолчанию: shared_buffers 128 МБ (16 384 буфера), full_page_writes = on.

docker run -d --name dba-crash-recovery-redo-pg -e POSTGRES_PASSWORD=pg postgres:18
docker exec -i dba-crash-recovery-redo-pg psql -U postgres <<'SQL'
ALTER SYSTEM SET checkpoint_timeout = '15min';
ALTER SYSTEM SET max_wal_size = '16GB';
SELECT pg_reload_conf();
SQL
docker exec dba-crash-recovery-redo-pg pgbench -U postgres -i -s 20 postgres

Опыт: kill -9 посреди pgbench

Порядок: принудительная контрольная точка, 4 клиента pgbench на 60 секунд, SIGKILL контейнеру. Команда docker kill -s KILL посылает сигнал postmaster’у (PID 1 контейнера), контейнер останавливается, все процессы PostgreSQL умирают без сброса чего-либо. Каталог данных лежит в томе и остаётся на месте.

C=dba-crash-recovery-redo-pg
docker exec -i $C psql -U postgres -c "CHECKPOINT"
docker exec -i $C psql -U postgres -Atc "select checkpoint_lsn, redo_lsn from pg_control_checkpoint()"
docker exec -d $C pgbench -n -U postgres -c 4 -j 2 -T 300 postgres
sleep 60
docker exec -i $C psql -U postgres -Atc "select pg_current_wal_insert_lsn(), pg_size_pretty(pg_wal_lsn_diff(pg_current_wal_insert_lsn(), redo_lsn)) from pg_control_checkpoint()"
docker kill -s KILL $C

вывод
0/5B5E7320|0/5B5E72C8
0/6FF8C798|330 MB

Первая строка — адрес записи checkpoint и его REDO-адрес. Вторая — позиция вставки в WAL за мгновение до kill и расстояние до REDO: 330 МБ журнала, которых нет в файлах таблиц. Контейнер остановлен, но каталог читается из соседнего контейнера с тем же томом:

docker run --rm --volumes-from $C postgres:18 pg_controldata /var/lib/postgresql/18/docker | grep -E "cluster state|Latest checkpoint location|REDO location"

вывод
Database cluster state:               in production
Latest checkpoint location:           0/5B5E7320
Latest checkpoint's REDO location:    0/5B5E72C8

Состояние in production у остановленного сервера — признак аварии: при чистой остановке там было бы shut down. Теперь запуск и лог:

docker start $C && sleep 6 && docker logs --since 20s $C 2>&1 | grep -E "interrupted|not properly|redo starts|invalid record|redo done|end-of-recovery|ready to accept"

вывод
20:49:52.244 UTC [32] LOG:  database system was interrupted; last known up at 2026-10-27 20:48:48 UTC
20:49:52.255 UTC [32] LOG:  database system was not properly shut down; automatic recovery in progress
20:49:52.256 UTC [32] LOG:  redo starts at 0/5B5E72C8
20:49:53.356 UTC [32] LOG:  invalid record length at 0/6FF923E8: expected at least 24, got 0
20:49:53.357 UTC [32] LOG:  redo done at 0/6FF923C0 system usage: CPU: user: 0.50 s, system: 0.56 s, elapsed: 1.10 s
20:49:53.358 UTC [30] LOG:  checkpoint starting: end-of-recovery immediate wait
20:49:53.853 UTC [1] LOG:  database system is ready to accept connections

redo starts at 0/5B5E72C8 совпадает с REDO location из pg_control, не с адресом самой записи checkpoint (0/5B5E7320): страницы, изменённые после начала точки, могли не успеть на диск, поэтому читать нужно с её начала. Журнал заканчивается там, где следующая запись нулевая: «invalid record length … got 0» здесь нормальный конец, а не повреждение. Между «redo done» и «ready» стоит ещё один checkpoint: в его строке checkpoint complete значится wrote 16202 buffers (98.9%), total=0.491 s, redo lsn=0/6FF923E8. Redo оставил в памяти почти все 16 384 буфера грязными, и их записали до открытия сервера: 0,49 с к 1,10 с redo. REDO-адрес новой точки стоит в конце журнала.

Что читает старт

Код InitWalRecovery берёт положение checkpoint и REDO-адрес из структуры, прочитанной из pg_control (тег REL_18_6, xlogrecovery.c, строки 790-794):

		CheckPointLoc = ControlFile->checkPoint;
		CheckPointTLI = ControlFile->checkPointCopy.ThisTimeLineID;
		RedoStartLSN = ControlFile->checkPointCopy.redo;
		RedoStartTLI = ControlFile->checkPointCopy.ThisTimeLineID;
		record = ReadCheckpointRecord(xlogprefetcher, CheckPointLoc,

В RedoStartLSN лежит то самое 0/5B5E72C8 из лога. Дальше PerformWalRecovery через ApplyWalRecord вызывает rm_redo для каждой записи от этого адреса и в конце печатает redo done.

Образ страницы в WAL: что с ним делает redo

Первая правка страницы после checkpoint кладёт в WAL её целиком. Одна строка до и после CHECKPOINT:

docker exec -i $C psql -U postgres -c "CHECKPOINT"
docker exec -i $C psql -U postgres -c "update pgbench_accounts set abalance=abalance+1 where aid=1"
docker exec -i $C psql -U postgres -c "update pgbench_accounts set abalance=abalance+1 where aid=2"
docker exec $C bash -c "cd /var/lib/postgresql/18/docker/pg_wal && pg_waldump -p . -s <LSN после CHECKPOINT> -e <LSN после обновлений> -b | grep -v RUNNING_XACTS"

вывод
rmgr: Heap   len (rec/tot):  65/ 8169, tx: 294606, lsn: 0/9DEEF9D0, ... desc: HOT_UPDATE ...
	blkref #0: rel 1663/5/57359 fork main blk 0 (FPW); hole: offset: 296, length: 88
rmgr: Heap   len (rec/tot):  71/   71, tx: 294607, lsn: 0/9DEF1A40, ... desc: HOT_UPDATE ...
	blkref #0: rel 1663/5/57359 fork main blk 0

Первое обновление записано как 8 169 байт и помечено (FPW), второе, в тот же блок 0, занимает 71. Образ с пропущенной «дырой» (hole, 88 байт между указателями строк и данными) весит почти ровно страницу. В пробеге из 60 секунд такие образы дали 295 004 748 из 343 183 953 байт журнала по pg_waldump --stats=record, то есть 85,96 %. Что именно делает с ними redo, показывает XLogReadBufferForRedoExtended: если у записи есть образ, страница перезаписывается им, старое содержимое не читается, а иначе сравнивается LSN:

			if (lsn <= PageGetLSN(BufferGetPage(*buf)))
				return BLK_DONE;
			else
				return BLK_NEEDS_REDO;

Страница, уже содержащая это изменение, пропускается (BLK_DONE), поэтому проигрывать журнал можно сколько угодно раз и с любого достаточно раннего места. Зачем образ нужен при обрыве записи страницы, разбирает статья про полные страницы, а сколько стоит частота точек — статья про checkpoint.

Что с оборванными транзакциями

В PostgreSQL откатывать нечего: у транзакции без записи COMMIT в pg_xact статус «не зафиксирована», и её версии строк просто невидимы. Проверка: транзакция меняет строку, другая зафиксированная обновляет соседнюю строку (чтобы WAL сбросился за изменением первой), затем kill.

( docker exec -i $C psql -U postgres -Atq -c "begin" -c "update pgbench_accounts set abalance = abalance + 5000 where aid = 77" -c "select pg_current_xact_id()" -c "select pg_sleep(120)" > xid.txt & )
docker exec -i $C psql -U postgres -Atq -c "update pgbench_accounts set abalance = abalance + 1 where aid = 78"
docker kill -s KILL $C
docker run --rm --volumes-from $C postgres:18 pg_waldump -p /var/lib/postgresql/18/docker/pg_wal -s <REDO> -x 294608
docker start $C && sleep 6 && docker exec -i $C psql -U postgres -Atq -c "select pg_xact_status('294608'::xid8)" -c "select abalance from pgbench_accounts where aid = 77"

вывод
rmgr: Heap   len (rec/tot):  65/ 8165, tx: 294608, lsn: 0/9DEF21C8, ... desc: HOT_UPDATE ...
aborted
0

Для транзакции 294608 в журнале есть одно изменение и нет ни COMMIT, ни ABORT; после старта pg_xact_status возвращает aborted, а значение строки по-прежнему 0. Работы по откату при запуске не было: в логе восстановления нет ни одной строки про откат. Согласованность по всему пробегу проверяет инвариант pgbench: sum(abalance), sum(bbalance), sum(tbalance) и sum(delta) из pgbench_history обязаны совпасть.

вывод
-2325577|-2325577|-2325577|-2325577|105217

Четыре суммы равны (последнее число — строк в pgbench_history), хотя kill пришёлся на работающих 4 клиентов: каждая транзакция меняет все четыре таблицы разом, и после старта видны либо все её изменения, либо ни одного.

Сколько длится redo

Тот же сценарий с паузой 10, 30 и 60 секунд, строки redo starts at и redo done at из лога:

Время растёт быстрее объёма: 32,7 МиБ проигрались за 0,03 с, а в десять раз больший журнал — в 37 раз дольше. Вероятная причина видна в последнем столбце: при 220 и 330 МиБ буферы заполнены почти целиком (16 284 и 16 202 из 16 384), и redo приходится вытеснять и перечитывать страницы; отдельно это не измерялось. Надёжна лишь верхняя граница: redo читает ровно то, что накопилось после последнего checkpoint, а накапливаться этому позволяют checkpoint_timeout (по умолчанию 5 минут) и max_wal_size (по умолчанию 1024 МБ). Оценить цену аварии «прямо сейчас» можно без аварии: pg_size_pretty(pg_current_wal_lsn() - redo_lsn) FROM pg_control_checkpoint() даёт объём, который старт проиграет.

InnoDB: redo вперёд, потом undo назад

InnoDB также ищет последнюю контрольную точку и накатывает redo, но затем откатывает транзакции, которые были живы в момент аварии: их изменения уже в страницах, а прежние значения лежат в undo.

docker run -d --name dba-crash-recovery-redo-my -e MYSQL_ROOT_PASSWORD=pg mysql:8.4 --log-error-verbosity=3

В таблице d.t 1 000 строк с v = 0. Сессия A выполняет UPDATE d.t SET v = 999 WHERE id <= 500 и не фиксируется; сессия B фиксирует 300 отдельных UPDATE ... SET v = v + 1 по другим строкам. До kill information_schema.innodb_trx показывает RUNNING и trx_rows_modified = 500.

После docker kill -s KILL и docker start лог (--log-error-verbosity=3, дата в строках срезана):

вывод
[Note] [MY-012560] [InnoDB] The log sequence number 29476089 in the system tablespace does not match the log sequence number 29655869 in the redo log files!
[Note] [MY-012552] [InnoDB] Starting crash recovery.
[Note] [MY-012550] [InnoDB] Doing recovery: scanned up to log sequence number 29929241
[Note] [MY-012532] [InnoDB] Applying a batch of 524 redo log records ...
[Note] [MY-013014] [InnoDB] Starting in background the rollback of uncommitted transactions
[Note] [MY-013011] [InnoDB] Rolling back trx with id 1815, 500 rows to undo
[Note] [MY-013012] [InnoDB] Rollback of trx with id 1815 completed
[Note] [MY-013015] [InnoDB] Rollback of non-prepared transactions completed

Перед kill SHOW ENGINE INNODB STATUS показывал Log sequence number 29929241 и Last checkpoint at 29655869: между ними 273 372 байта redo, а scanned up to log sequence number в логе дошёл ровно до 29929241. Затем идёт откат транзакции 1815 на 500 строк, 5 мс по времени строк лога. Итог: v = 0 в 700 строках, v = 999 — ни в одной, v = 1 — в 300 зафиксированных. Ветка выбора находится в recv_recovery_from_checkpoint_start (mysql-8.4.13):

    if (!recv_needed_recovery) {
      ib::info(ER_IB_MSG_RECOVERY_IS_NEEDED, ulonglong{flush_lsn},
               ulonglong{checkpoint_lsn});

      if (srv_read_only_mode) {
        ib::error(ER_IB_MSG_RECOVERY_IN_READ_ONLY);

        return DB_ERROR;
      }

      recv_init_crash_recovery();
    }
  }

  err = recv_recovery_begin(log, checkpoint_lsn);

Первая строка внутри if печатает «does not match» из лога, recv_recovery_begin накатывает redo от checkpoint_lsn. Откат запускается позже и в фоне (trx_rollback_active в trx0roll.cc печатает «Rolling back trx … rows to undo»).

SQLite: журнал отката и WAL

SQLite без WAL пишет в файл базы сразу, а прежнее содержимое страниц сохраняет в t.db-journal. При обрыве этот «горячий» журнал остаётся рядом, и следующее открытие базы возвращает из него страницы. Опыт: 20 000 строк, UPDATE каждой на +1000 внутри транзакции с cache_size=10 (грязные страницы вытесняются в файл), затем SIGKILL самому процессу Python.

db = sqlite3.connect('t.db', isolation_level=None)
db.execute('PRAGMA cache_size=10')
db.execute('BEGIN')
db.execute('UPDATE t SET v = v + 1000')
os.kill(os.getpid(), signal.SIGKILL)

вывод
до kill: ['t.db', 't.db-journal']
копия t.db без журнала: [(20000, 19893000)] ('ok',)
оригинал с журналом:    [(20000, 0)]

Файл базы без журнала содержит половинчатое состояние: сумма v равна 19 893 000 вместо 0, причём integrity_check отвечает ok, потому что каждая страница цела. Вместе с журналом (4 492 824 байта) открытие возвращает базу в состояние до транзакции, а журнал исчезает. Эту логику выполняет pager_playback (тег version-3.50.2): по её комментарию, горячий журнал сначала сбрасывает кэш страниц, а потом откатывает содержимое.

В режиме WAL тот же обрыв оставляет t.db-wal в 4 313 672 байта с кадрами без метки фиксации. База читается как (20000, 0), потому что читатели игнорируют кадры незавершённой транзакции, а сам файл базы не менялся.

Что из этого следует

• Простой после аварии PostgreSQL = redo + запись грязных страниц. Первая часть растёт с объёмом WAL после последнего checkpoint, вторая — с числом грязных буферов. Растягивая checkpoint_timeout, ты сглаживаешь запись, но платишь временем старта.
• Оборванная транзакция PostgreSQL не добавляет работы при старте, в InnoDB добавляет. Там после redo идёт откат по undo: 500 строк заняли 5 мс, и время растёт вместе с числом изменённых строк (trx_rows_modified). Для длинной транзакции этот откат идёт в фоне уже после запуска.

Чек-лист

• После аварии найди в логе redo starts at, redo done at ... elapsed и checkpoint complete с end-of-recovery: их сумма — простой.
• Раз в сутки снимай pg_size_pretty(pg_current_wal_lsn() - redo_lsn) FROM pg_control_checkpoint(): пик показывает, сколько проиграется при аварии.
• Не удаляй сегменты pg_wal вручную: pg_controldata называет сегмент, без которого старт невозможен.
• В InnoDB перед аварийной остановкой смотри information_schema.innodb_trx: trx_rows_modified оценивает объём отката.