Привет! Я Александр Никитин, DBA компании Data Egret.
Сегодня я хочу поговорить с вами про такую замечательную вещь как Point in time recovery (PITR) в PostgreSQL.
Механизм восстановления на определенную точку во времени работает таким образом – у нас есть базовый бэкап, созданный при помощи какой-либо утилиты создания бэкапов (например pg_basebackup), а также набор журнальных файлов, постепенно применяя (накатывая) который, мы можем восстановиться до указанной точки.
Звучит это довольно просто, но, как водится, в каждой простой вещи есть какие-то нюансы, вот о них мы сегодня с вами и поговорим.
Возникает задача восстановиться на точку во времени. И было бы всё просто если бы мы знали на какую именно точку нам нужно восстановиться, но что, если мы не знаем? Что если к нам приходит пользователь и говорит – минут 10-15 тому назад была удалена важная таблица, нужно восстановить кластер на точку которая была непосредственно, перед командой удаления таблицы. Или, например, в определённой очень важной таблице была очень важная запись, её по ошибке удалили и теперь всё плохо, нужно восстановиться до максимального момента, когда запись ещё была жива.
В этой статье мы не будем рассматривать подробно настройку бэкапов, я буду исходить из предположения, что базовый бэкап у вас уже создан, wal-файлы копируются в отдельное место и в целом вы уже знаете как производить восстановление, но не знаете как определить конечную точку восстановления.
Удаление таблицы
Пришел пользователь и сообщил нам о том, что в результате ошибочных действий исчезла таблица. Давайте смоделируем эту ситуацию.
Но перед тем как идти и всё портить, давайте проверим значение, установленное в log_statement:
show log_statement;
log_statement
---------------
none
Это значение по-умолчанию, далее мы рассмотрим какие ещё бывают значения и поймём, как изменение этого значения может нам помочь.
Создадим таблицу и наполним её данными:
create table t0 as
SELECT
(random() * 1e6)::integer as num
, now() - random() * '1 year'::interval as date_num
FROM
generate_series(1, 1e5) id;
Ради интереса давайте сначала сделаем truncate и только потом drop, при этом мы будем смотреть на номера транзакций при помощи вызова перед каждой операцией функции txid_current().
Получим следующее:
Действие | Номер транзакции |
|
|
|
|
|
|
|
|
|
|
Конечно, на моём тестовом стенде работаю только я, но уже становится понятно, что команды truncate и drop вызывались в отдельных транзакциях.
Посмотрим, какой wal-файл является текущим:
select pg_walfile_name(pg_current_wal_lsn());
pg_walfile_name
--------------------------
00000002000000000000000D
В поставку PostgreSQL входит утилита pg_waldump, которая поможет нам разобраться с тем, что происходит, нужно передать ей в качестве параметра имя интересующего нас журнала, перейдём в $PGDATA/pg_wal и выполним:
/usr/pgsql-13/bin/pg_waldump 00000002000000000000000D
Выйдет много строк подобных этим:
rmgr: Heap len (rec/tot): 71/ 71, tx: 509, lsn: 0/0D46A030, prev 0/0D469FD0, desc: INSERT off 26 flags 0x08, blkref #0: rel 1663/16384/32769 blk 340
rmgr: Heap len (rec/tot): 71/ 71, tx: 509, lsn: 0/0D46A078, prev 0/0D46A030, desc: INSERT off 27 flags 0x08, blkref #0: rel 1663/16384/32769 blk 340
Уберём из вывода то, что нас не будет интересовать:
/usr/pgsql-13/bin/pg_waldump 00000002000000000000000D | awk '{out=""; for(i=7;i<=NF;i++){if(i>=11&&i<=12) continue; else out=out" "$i}; print out}'| cut -c1-150
Для того, чтобы не писать эту команду каждый раз, я обозначу её как LONG_COMMAND, и если далее вы увидите упоминание LONG_COMMAND, вы должны будете подставить вместо него текст самой команды.
Из таблицы, которую мы составили ранее, можно увидеть, что truncate таблицы произошёл в транзакции 511.
И, действительно, если мы внимательно посмотрим на то, что стоит напротив транзакции 511 мы можем увидеть среди прочих такие строки:
LONG_COMMAND|grep 'tx: 511'
…
tx: 511, lsn: 0/0D6F7E20, desc: TRUNCATE nrelids 1 relids 32769
tx: 511, lsn: 0/0D6F7E50, desc: COMMIT 2022-08-26 13:07:07.027629 +07; rels: base/16384/32769; inval msgs: catcache 50 catcache 49 relcache 32769
…
Таким образом, если мы хотим быстро найти в wal-логе номер транзакции, которая очистила таблицу, мы можем написать:
LONG_COMMAND|grep TRUNCATE -A1
На экране появятся те строчки, которые мы видели выше.
Теперь мы знаем и время коммита очищающей транзакции и её номер. Используя эти параметры мы можем произвести восстановление на нужную нам точку времени.
Позднее в статье будут приведены примеры подобных команд.
Дальше у нас шла команда удаления таблицы, давайте посмотрим, как она отображается в записях журнала (это была транзакция номер 513):
LONG_COMMAND|grep 'tx: 513'
…
tx: 513, lsn: 0/0D6F8598, desc: DELETE off 131 flags 0x00 KEYS_UPDATED , blkref #0: rel 1663/16384/2608 blk 56
tx: 513, lsn: 0/0D6F85D0, desc: COMMIT 2022-08-26 13:07:07.031125 +07; rels: base/16384/32772; inval msgs: catcache 7 catcache 6 catcache 7 catcache
…
Как мы видим, последняя значимая строчка содержит слова inval msgs.
Но, если мы будем искать по этим словам, то увидим, что они возникают и после создания таблицы и после того, как мы её очистили, также они возникают и после того, как мы удаляем таблицу.
LONG_COMMAND|grep "inval msgs"
tx: 509, lsn: 0/0D6F7A18, desc: COMMIT 2022-08-26 13:07:07.011185 +07; inval msgs: catcache 75 catcache 74 catcache 75 catcache 74 catcache 50 catcac
tx: 511, lsn: 0/0D6F7E50, desc: COMMIT 2022-08-26 13:07:07.027629 +07; rels: base/16384/32769; inval msgs: catcache 50 catcache 49 relcache 32769
tx: 513, lsn: 0/0D6F85D0, desc: COMMIT 2022-08-26 13:07:07.031125 +07; rels: base/16384/32772; inval msgs: catcache 7 catcache 6 catcache 7 catcache
Посмотрим шире на то, что видно в логах (найдём нужную нам строчку и выведем не только её, но и строчку, которая находится выше):
LONG_COMMAND|grep "inval msgs" -B 1
…
tx: 509, lsn: 0/0D6F79D0, desc: INSERT off 100 flags 0x08, blkref #0: rel 1663/16384/32769 blk 540
tx: 509, lsn: 0/0D6F7A18, desc: COMMIT 2022-08-26 13:07:07.011185 +07; inval msgs: catcache 75 catcache 74 catcache 75 catcache 74 catcache 50 catcac
--
tx: 511, lsn: 0/0D6F7E20, desc: TRUNCATE nrelids 1 relids 32769
tx: 511, lsn: 0/0D6F7E50, desc: COMMIT 2022-08-26 13:07:07.027629 +07; rels: base/16384/32769; inval msgs: catcache 50 catcache 49 relcache 32769
--
tx: 513, lsn: 0/0D6F8598, desc: DELETE off 131 flags 0x00 KEYS_UPDATED , blkref #0: rel 1663/16384/2608 blk 56
tx: 513, lsn: 0/0D6F85D0, desc: COMMIT 2022-08-26 13:07:07.031125 +07; rels: base/16384/32772; inval msgs: catcache 7 catcache 6 catcache 7 catcache
Мы видим, что только если перед строкой inval msgs находится DELETE, то можно можно считать, что это отрабатывала команда drop table.
Другими словами, вычислить транзакцию во время которой была удалена таблица можно таким образом:
LONG_COMMAND|grep "inval msgs" -B1|grep DELETE -A1
…
tx: 513, lsn: 0/0D6F8598, desc: DELETE off 131 flags 0x00 KEYS_UPDATED , blkref #0: rel 1663/16384/2608 blk 56
tx: 513, lsn: 0/0D6F85D0, desc: COMMIT 2022-08-26 13:07:07.031125 +07; rels: base/16384/32772; inval msgs: catcache 7 catcache 6 catcache 7 catcache
Давайте восстановим нашу базу из бэкапа на точку во времени, когда таблица ещё существовала и в ней были записи. Для этого находим точное время коммита транзакции, указываем это время и обязательно указываем параметр recovery_target_inclusive='false', который сообщит процессу восстановления то, что необходимо прервать восстановление непосредственно перед указанной точкой:
/usr/pgsql-13/bin/pg_ctl start -D /var/lib/pgsql/13/data -o "-c recovery_target_time='2022-08-26 13:07:07.027629+07'" -o "-c recovery_target_inclusive='false'" -o "-c recovery_target_action='pause'"
Такого же результата можно добиться, если указать номер транзакции или lsn. Для этого нужно будет поменять recovery_target_time на:
"-c recovery_target_xid=511" или
"-c recovery_target_lsn='0/0D6F7E50'"
Теперь давайте попробуем установить log_statement в ddl:
set log_statement = 'ddl';
И повторим те же действия с таблицей – создадим, очистим и удалим. После этого мы заглянем в лог-файлы:
2022-08-26 14:27:44.445 +07 [13600] LOG: statement: create table t0 as …
2022-08-26 14:27:44.695 +07 [13600] LOG: statement: drop table t0;
Как видно, каждая из ddl-операций нашла своё отражение в текстовых логах базы (напомню, что truncate не является командой ddl), таким образом, для определения каких-то точек не обязательно лезть в wal-файлы и искать точное значение там.
Помимо этого, даже если в уровень log_statement = none, но с удалённой таблицей регулярно производилась работа, то помочь найти хотя бы примерное время удаления можно через логи. Как только таблица будет удалена, то следующее же обращение к ней выдаст ошибку, которая попадёт в лог:
2022-08-26 14:31:23.587 +07 [13638] ERROR: relation "t0" does not exist at character 15
Глядя на время появления подобных ошибок можно найти набор wal-файлов, соответствующий этому периоду времени и найти в них точное время/транзакцию/lsn операции удаления таблицы.
В следующей части мы попробуем найти момент удаления той или иной записи.
