如何验证 PostgreSQL 基础 + WAL 备份是否已正确恢复

Question

同事们试图从 9.1 版本的热备备份中提取 PostgreSQL 数据库副本，但它并不可靠 - 我们每天都会运行它，但通常在对副本运行查询时最终会出现各种错误。

遗憾的是，我无法在网络上找到关于原因的明确答案，并且在 PostgreSQL IRC 频道中需要一个善良的灵魂来让我直截了当 - 不支持从备用数据库中进行这样的备份-那个版本中的盒子。

因此，为了其他可能遇到相同问题并尝试使用谷歌搜索的人的利益，我将在下面的答案中写下我们的笔记。

Answer 1

答案将包含两个部分 - 首先，恢复后日志中可以看到的内容，其次是一些不可接受的示例。第一部分应该是相当确定的，而第二部分基本上是对发生在我们身上的表明我们有问题的任何事情的随机分类。

可接受的日志输出

在开始时：

2015-07-23 06:51:24 UTC LOG: database system was interrupted; last known up at 2015-07-23 02:10:42 UTC

重要的是要看到正在恢复的 PostgreSQL 知道它上次运行的时间。我认为是这样，因为这意味着它是从检查点开始的。

xlog min recovery request ... 已超过当前点

一开始，可能会发生以下几种情况：

2015-07-23 06:51:30 UTC WARNING:  xlog min recovery request 1027/B0A28D98 is past current point 1027/2BE36DA8
2015-07-23 06:51:30 UTC CONTEXT:  writing block 0 of relation base/117264/9551898_vm
       xlog redo insert: rel 1663/117264/8310261; tid 68622/40

但根据http://www.postgresql.org/message-id/CAB7nPqTd43hqpuC+M8fo+xkqHv1WtFe_16NUttu1pHcBtZhZmw@mail.gmail.com这是无害的

FATAL：数据库系统正在启动

任何数量的这些都可能发生：

2015-07-23 06:51:24 UTC FATAL:  the database system is starting up

这实际上应该是无害的，因为在我们的案例中，它们是SELECT 1脚本运行以检查 PostgreSQL 是否准备就绪的自动ping 类查询的结果。

意外的 pageaddr ... 在日志文件 ...，段 ...，偏移量 ...

最后是这样的：

2015-07-23 06:52:21 UTC LOG:  restored log file "0000000100001027000000B2" from archive
2015-07-23 06:52:21 UTC LOG:  consistent recovery state reached at 1027/B2F8F2F8
sh: 1: cannot open ../../../wal_backup/0000000100001027000000B3: No such file
2015-07-23 06:52:21 UTC LOG:  unexpected pageaddr 1027/AA000000 in log file 4135, segment 179, offset 0
2015-07-23 06:52:21 UTC LOG:  redo done at 1027/B2F8F2F8
2015-07-23 06:52:21 UTC LOG:  last completed transaction was at log time 2015-07-23 02:17:33.842307+00

但根据http://www.postgresql.org/message-id/CAGrpgQ-BbXUNErrAtToYhRyUef9_GdUQz1T3CXbpTMLTnuKANQ@mail.gmail.com这也是无害的

请注意，在那之后可能会有更多的 WAL 恢复：

2015-07-23 06:52:21 UTC LOG:  restored log file "0000000100001027000000B2" from archive

这仅仅意味着您提供了recovery.conf比严格必要的更多的 WAL 文件。

00000002.history：没有这样的文件

在 WAL 展开过程的最后，是这样的：

sh: 1: cannot open ../../../wal_backup/00000002.history: No such file
2015-07-23 06:52:21 UTC LOG:  selected new timeline ID: 2
sh: 1: cannot open ../../../wal_backup/00000001.history: No such file
2015-07-23 06:52:21 UTC LOG:  archive recovery complete

这显然/希望无关，因为这是恢复的数据库（克隆）开始新生活（时间线）的地方。

不可接受的日志输出

在开始时：

2015-07-20 12:38:31 UTC LOG: database system was interrupted while in recovery at log time 2015-07-20 01:41:22 UTC

这很关键——这意味着备份过程没有在正确的时间开始——在pg_start_backup(...)检查点之后——而是数据库正常工作并且处于某个随机点，这意味着这种恢复更类似于恢复崩溃的数据库。

pg_toast 中缺少块...

这表明还原不正确。作为快速修复，我们尝试了http://postgresql.nabble.com/select-table-indicate-missing-chunk-number-0-for-toast-value-96635-in-pg-toast-2619- td5682176.html

mydb=# vacuum analyze mytable; -- trigger the error to see the problem toast
ERROR:  missing chunk number 0 for toast value 13044178 in pg_toast_2619
mydb=# reindex table pg_toast.pg_toast_2619;
REINDEX

这有时会使桌子恢复到工作状态，但有时也不会产生这种效果。之后我们又戳了戳它，认为我们发现它只是 pg_statistic 是一次性的：

mydb=# reindex table pg_statistic;
ERROR:  could not create unique index "pg_statistic_relid_att_inh_index"
DETAIL:  Key (starelid, staattnum, stainherit)=(884792, 34, f) is duplicated.
mydb=# delete from pg_statistic;
DELETE 188540
mydb=# reindex table pg_statistic;
REINDEX
mydb=# vacuum analyze mytable;
VACUUM

右兄弟的左链接不匹配

CREATE TABLE "myschema"."mytable" ( ... )
ERROR: right sibling's left-link doesn't match: block 27 links to 21379 instead of expected 21393 in index "pg_depend_reference_index"

我们尝试通过以下方式快速绕过此问题：

mydb=# set zero_damaged_pages=on;
SET
mydb=# reindex table pg_depend;
REINDEX
mydb=# set zero_damaged_pages=off;
SET

无法读取文件中的块...

2015-05-12 13:32:53 UTC ERROR:  could not read block 76408 in file "pg_tblspc/4606764/PG_9.1_201105231/117264/4614269": read only 0 of 8192 bytes

这显然是一个无赖。我们无法快速解决这个问题：

mydb=# select cl.relfilenode, nsp.nspname as schema_name, cl.relname, cl.relkind from pg_class cl join pg_namespace nsp on cl.relnamespace = nsp.oid where relfilenode = 4614269;
 relfilenode | schema_name | relname | relkind
-------------+-------------+---------+---------
     4614269 | myschema    | mytable | r
(1 row)

mydb=# select pg_relation_filepath('myschema.mytable');
               pg_relation_filepath
---------------------------------------------------
 pg_tblspc/4606764/PG_9.1_201105231/117264/4614269
(1 row)

% sudo ls -lah /var/lib/postgresql/9.1/main/pg_tblspc/4606764/PG_9.1_201105231/117264/4614269
-rw------- 1 postgres postgres 597M May 11 19:22 /var/lib/postgresql/9.1/main/pg_tblspc/4606764/PG_9.1_201105231/117264/4614269

这是一个很好的指标，表明“丢失”了太多数据。

重复键值违反唯一约束“pg_type_typname_nsp_index”

这是恢复被破坏的另一个指标：

CREATE TABLE "myschema"."mytable" ( ... )
ERROR: duplicate key value violates unique constraint "pg_type_typname_nsp_index" DETAIL: Key (typname, typnamespace)=(mytable_mycolumn_seq, 3780903) already exists.

对此的快速技巧是移动序列位置：

SELECT setval('mytable_id_seq', (SELECT MAX(id) FROM mytable));