Куда мы катимся? Вторая часть
Продолжим наше знакомство с Point in time Recovery.
В первой части мы рассмотрели ситуацию, когда нужно найти момент, в который была очищена таблица и произвели восстановление до точки, находящейся перед этим событием.
В этот раз мы рассмотрим более сложную ситуацию.
Удаление записи.
Представьте, что у вас есть очень важная таблица с очень важными записями, настолько важными, что всё остальное по сравнению с ними незначительно и вот к нам приходит пользователь и сообщает о том, что какая-то запись из этой таблицы пропала. Нужно срочно восстанавливать базу данных из бэкапа до последнего момента, когда эта запись ещё была жива.
Сгенерируем тестовую таблицу точно так же, как в первой части:
create table t0 as
SELECT
(random() * 1e6)::integer as num
, now() - random() * '1 year'::interval as date_num
FROM
generate_series(1, 1e5) id;
Запомним номер текущей транзакции:
select txid_current(); - 531
Удалим какую-нибудь запись (или несколько записей):
delete from t0 where num in (select num from t0 order by random() limit 1) returning *;
Итак, волею случая была удалена следующая запись:
num | date_num
------+-------------------------------
3214 | 2022-08-01 11:43:06.709451+07
select txid_current(); - 533
Становится понятно, что удаление было произведено в транзакции 532, давайте посмотрим, как это выглядит с точки зрения wal-файлов.
Узнаем название текущего журнала:
select pg_walfile_name(pg_current_wal_lsn());
pg_walfile_name
--------------------------
00000002000000000000000F
/usr/pgsql-13/bin/pg_waldump 00000002000000000000000F | awk '{out=""; for(i=7;i<=NF;i++){if(i>=11&&i<=12) continue; else out=out" "$i}; print out}'| cut -c1-150|grep 'tx: 532'
...
tx: 532, lsn: 0/0F2C2B58, desc: DELETE off 118 flags 0x00 KEYS_UPDATED , blkref #0: rel 1663/16384/32784 blk 123 FPW
tx: 532, lsn: 0/0F2C4B90, desc: COMMIT 2022-08-26 18:51:59.613232 +07
Что мы можем извлечь из этой информации? Мы видим, что была транзакция, которая произвела какое-то удаление в rel 1663/16384/32784 в блоке номер 123 и эта транзакция была закоммичена в 2022–08–26 18:51:59.613232 +07.
Вызовем функцию pg_relations_filepath для нашей таблицы:
select pg_relation_filepath('t0');
pg_relation_filepath
----------------------
base/16384/32784
Как видно, речь идёт именно о нашей таблице.
Что же ещё мы можем вытащить из вывода pg_waldump? Например, для нас может представлять интерес номер блока, в котором была удалена запись — как видно из примера — здесь он имеет номер 123. Давайте установим расширение pageinspect и посмотрим, что же содержится в этом блоке:
SELECT * FROM heap_page_item_attrs(get_raw_page('t0',123), 't0'::regclass, true );
lp | lp_off | lp_flags | lp_len | t_xmin | t_xmax | t_field3 | t_ctid | t_infomask2 | t_infomask | t_hoff | t_bits | t_oid | t_attrs
...
117 | 3512 | 1 | 40 | 530 | 0 | 1 | (123,117) | 2 | 2304 | 24 | | | {"\\x4d7b0e00","\\x4b9ed334fb750200"}
118 | 3472 | 1 | 40 | 530 | 532 | 0 | (123,118) | 8194 | 256 | 24 | | | {"\\x8e0c0000","\\xcb9d996725880200"}
119 | 3432 | 1 | 40 | 530 | 0 | 1 | (123,119) | 2 | 2304 | 24 | | | {"\\x1fa50300","\\x4b13691361810200"}
Мы видим, что в одной из записей в поле t_xmax как раз стоит номер транзакции, которая произвела удаление.
8e0c0000 довольно легко преобразуется в десятичную форму записи:
0с8e (hex) → 3214(dec) — это как раз значение num в удалённой записи.
Пожалуй, этого нам хватит.
Теперь мы можем обобщить полученную информацию:
1) Зная примерное время удаления записи мы можем, используя pg_waldump, проанализировать состав wal-файлов за этот временной промежуток.
2) Зная oid нашей таблицы мы можем добавить дополнительное условие в вывод pg_waldump, которое будет показывать только те записи журнала, что относятся к интересующей нас таблице.
3) Зная номера блоков при помощи pageinspect мы можем детально посмотреть какие записи были удалены.
4) Теперь, если, к примеру у нас было несколько удалений, то мы уже знаем в какой именно транзакции была удалена та или иная запись, а, значит, сможем и восстановиться на указанную временную точку.
5) Если же у нас нет вообще никаких предположений о том, когда именно была удалена запись, то мы можем написать небольшую функцию, которая пробежится по всем блокам таблицы и найдёт удалённые записи про которые мы что-то знаем (например, мы можем знать определенный признак записи типа идентификатора или текстового значения). Это довольно длительная по времени процедура, но она может принести свои плоды.
6) Но и последний подход можно ускорить, если, например, вы знаете что какие-то записи хотя бы предположительно лежат в этом же блоке. Например, если у нас используются не суррогатные ключи, а натуральные, то мы можем получить номера блоков содержащих близкие к удаленным значениям записи и проанализировать эти блоки на предмет наличия совпадений. Никто не даст гарантии, что в этих блоках будет содержаться удалённая запись, но этот подход гораздо быстрее, чем производить поиск по всей таблице.
Пришло время для реальных тестов!
1) Удалим произвольную запись (записи)
delete from t0 where num in (select num from t0 order by random() limit 1) returning *;
num | date_num
--------+-------------------------------
387899 | 2022-04-14 23:59:45.320651+07
387899 | 2022-07-04 18:57:33.762251+07
2) Создадим некую активность, чтобы после удаления нашей записи прошло какое-то время и мы не смотрели именно текущий wal-файл.
create table t2 as select * from t0;
insert into t2 select * from t2;
insert into t2 select * from t2;
insert into t2 select * from t2;
insert into t2 select * from t2;
drop table t2;
3) К нам приходит пользователь и говорит, что из нашей таблицы t0 пропала очень важная запись с Num = 387899 и произошло это совсем недавно, нужно восстановиться до момента, когда эта запись была удалена (не включая операцию удаления).
4) По выводу ls -lh в в директории pg_wal мы можем определить список wal-файлов в которых должна содержится информация об удалении.
В моём случае это файлы
Aug 29 18:23 00000002000000000000000F
…
Aug 29 18:25 000000020000000000000018
5) Мы уже знаем relfilenode таблицы, из которой произошло удаление, но на всякий случай проверим его ещё раз:
select pg_relation_filepath('t0'); - base/16384/32784
6) Начинаем парсить wal-логи, попавшие под подозрение:
/usr/pgsql-13/bin/pg_waldump /var/lib/pgsql/13/data/pg_wal/00000002000000000000000F 000000020000000000000018 | awk '{out=""; for(i=7;i<=NF;i++){if(i>=11&&i<=12) continue; else out=out" "$i}; print out}'| grep '16384/32784' -A1|grep DELETE -A1|cut -c1-150
pg_waldump: fatal: error in WAL record at 0/183CAC98: invalid record length at 0/183CACD0: wanted 24, got 0
tx: 532, lsn: 0/0F2C2B58, desc: DELETE off 118 flags 0x00 KEYS_UPDATED , blkref #0: rel 1663/16384/32784 blk 123 FPW
tx: 532, lsn: 0/0F2C4B90, desc: COMMIT 2022-08-26 18:51:59.613232 +07
--
tx: 535, lsn: 0/0F2FE530, desc: DELETE off 3 flags 0x00 KEYS_UPDATED , blkref #0: rel 1663/16384/32784 blk 227 FPW
tx: 535, lsn: 0/0F300568, desc: COMMIT 2022-08-29 18:22:12.309869 +07
--
tx: 542, lsn: 0/11594B40, desc: DELETE off 47 flags 0x00 KEYS_UPDATED , blkref #0: rel 1663/16384/32784 blk 154 FPW
tx: 542, lsn: 0/11596B78, desc: DELETE off 9 flags 0x00 KEYS_UPDATED , blkref #0: rel 1663/16384/32784 blk 366 FPW
tx: 542, lsn: 0/11598BB0, desc: COMMIT 2022-08-29 18:24:34.219091 +07
Мы видим, что за обозначенный промежуток времени было три удаления (я удалял данные до того как мы начали эксперимент), были затронуты следующие блоки — 123, 227, 154 и 366.
Скорее всего это была транзакция 542 — было удалено две записи, но ведь подглядывать в вывод операции delete нечестно, поэтому начинаем искать в этих блоках упоминание о том, какие записи были удалены:
7)
SELECT * FROM heap_page_item_attrs(get_raw_page('t0',123), 't0'::regclass, true ) where t_xmax !=0 or t_xmax is null;
SELECT * FROM heap_page_item_attrs(get_raw_page('t0',227), 't0'::regclass, true ) where t_xmax !=0 or t_xmax is null;
SELECT * FROM heap_page_item_attrs(get_raw_page('t0',154), 't0'::regclass, true ) where t_xmax !=0 or t_xmax is null;
SELECT * FROM heap_page_item_attrs(get_raw_page('t0',366), 't0'::regclass, true ) where t_xmax !=0 or t_xmax is null;
Все эти запросы ничего нам не дали (после удаления я делал запрос к таблице). Оказывается, что вступила в дело внутристраничная очистка (подробнее об этом механизме можно почитать в исходниках) и никаких вспомогательных данных из таблицы достать не получится.
На реальных данных вам может повезти больше чем мне и вы сможете оперативно обнаружить данные о том, какая же именно транзакция произвела удаление.
8) Поскольку мы ничего не нашли в блоках данных значит, при восстановлении мы можем ориентироваться только на данные из журналов wal.
Таким образом, сначала мы должны восстановиться до точки коммита первой транзакции, включая её, проверить, что данные ещё на месте. Если данные на месте, то продолжаем восстановление до следующего коммита. Если же после определённого коммита данные всё-таки исчезли, значит мы угадали точку и нужно повторить восстановление, но на этот раз исключить найденную точку из списка восстанавливаемых.
Для ускорения процесса воспользуемся следующей последовательностью команд:
/usr/pgsql-13/bin/pg_ctl start -D /var/lib/pgsql/13/data -o "-c recovery_target_xid=532" -o "-c recovery_target_action='pause'"
Далее проверяем, что наша запись ещё на месте, если её уже нет, значит нужные нам данные были удалены именно в 532 транзакции и мы производим восстановление снова до 532 транзакции, но на этот раз с опцией recovery_target_inclusive='false'
Ну, а если нам «повезло» и запись ещё на месте, то нужно перезапустить PostgreSQL с указанием другого recovery_target_xid.
Таким образом, последовательно перебирая транзакции вы сможете найти нужную вам точку.
Конечно, поиск в подобной ситуации может занять довольно длительное время, ведь при наличии более чем одного кандидата нужно будет производить как минимум два восстановления — первое, включающее точку удаления и второе, исключающее её. Но в каких-то случаях это может стать единственным вариантом решения поставленной перед нами задачи.
В заключение хочу пожелать вам как можно реже пользоваться информацией, полученной из моих статей!
