[译]Postgres15-新特性-利用pg_walinspect对WAL事件进行debug

yzsDBA

发布于 2023-02-26 05:11:02

98400

代码可运行

文章被收录于专栏：PostgreSQL研究与原理解析PostgreSQL研究与原理解析

运行总次数：0

代码可运行

利用pg_walinspect对WAL事件进行debug

Write Ahead Log即WAL是Postgres的核心部件，存储着写操作，帮助实现其事务的原子性、一致性和持久性。因为是二进制格式存储，如果需要调试写入活动，不借助工具仅靠肉眼很难读取。幸运的是，从9.3版本开始出现了“人类可读”的格式显示WAL记录的工具pg_xlogdump/pg_waldump。该工具可解析WAL日志，解读出人们可读的格式。

PostgreSQL15发布了一种新方法。通过pg_walinspect扩展使用纯SQL语言查看WAL内部发生情况。该扩展允许更加方便地检查WAL记录，用于调试和报告，甚至用于探索Postgres如何工作。

体验下pg_walinspect

第一步当然是安装扩展：

postgres=# CREATE EXTENSION pg_walinspect;

该扩展允许我们检查2个有效的WAL日志序列号（LSN）之间的记录：start_lsn和end_lsn。这些LSN可以通过pg_current_wal_lsn函数获取。

start_lsn可以通过下面方式获取：

postgres=# SELECT pg_current_wal_lsn(),now();
pg_current_wal_lsn |              now              
--------------------+-------------------------------
0/157BA88          | 2022-10-23 15:51:21.532482-03
(1 row)

我们为示例生成一些写入活动：CREATE TABLE-INSERT-DELETE操作：

postgres=# create table my_tab(i int, j text);
CREATE TABLE
postgres=# INSERT INTO my_tab VALUES(1,'1'),(2,'2');
INSERT 0 2
postgres=# DELETE FROM my_tab where i=1;
DELETE 1

以与start_lsn相同的方式获取end_lsn：

postgres=# SELECT pg_current_wal_lsn(),now();
pg_current_wal_lsn |              now              
--------------------+-------------------------------
0/157E768          | 2022-10-23 15:51:37.255149-03
(1 row)
pg_get_wal_record_info函数与提取的LSN（0/157BA88和 0/157E768）结合一起使用：
postgres=# select start_lsn, end_lsn, xid, resource_manager, record_type, record_length, main_data_length, fpi_length, description::varchar(30) from pg_get_wal_records_info('0/157BA88', '0/157E768');
--- the whole output will be at the end in a linked file
start_lsn | end_lsn  | xid | resource_manager |  record_type  | record_length | main_data_length | fpi_length |          description           
-----------+-----------+-----+------------------+---------------+---------------+------------------+------------+--------------------------------
0/157BA88 | 0/157BAB8 |   0 | Storage          | CREATE        |            42 |               16 |          0 | base/5/16415
0/157BAB8 | 0/157BB90 | 747 | Heap             | INSERT        |           211 |                3 |          0 | off 16 flags 0x00
0/157BB90 | 0/157BBD0 | 747 | Btree            | INSERT_LEAF   |            64 |                2 |          0 | off 252
...
...
...
0/157E6E0 | 0/157E708 | 748 | Transaction      | COMMIT        |            34 |                8 |          0 | 2022-10-23 15:51:29.170343-03
0/157E708 | 0/157E740 | 749 | Heap             | DELETE        |            54 |                8 |          0 | off 1 flags 0x00 KEYS_UPDATED 
0/157E740 | 0/157E768 | 749 | Transaction      | COMMIT        |            34 |                8 |          0 | 2022-10-23 15:51:34.056308-03
(100 rows)

WAL详细程度

输出的详细程度取决于wal_level设置。从最低（minimal）到最高（logical）。本案例中使用默认值replica。第一印象是 wal 记录的数量很多：仅针对几个 SQL 操作就生成了 100 条记录。如果wal_level设置为logical，记录数会增加（如果设置为minimal则记录数当然会减少）。

另一个观察结果是并非所有记录都具有相同的长度。这就是为什么并非所有活动都对数据库具有相同权重或影响的原因。

一般统计

可以使用pg_get_wal_stats函数查看LSN间隔中的一般统计信息：

postgres=# select * from pg_get_wal_stats('0/157BA88', '0/157E768', true) order by count_percentage desc;
resource_manager/record_type | count | count_percentage | record_size | record_size_percentage | fpi_size | fpi_size_percentage | combined_size | combined_size_percentage 
------------------------------+-------+------------------+-------------+------------------------+----------+---------------------+---------------+--------------------------
Btree/INSERT_LEAF            |    65 |               65 |        4456 |     39.725416778104666 |        0 |                   0 |          4456 |       39.416187527642634
Heap2/MULTI_INSERT           |    10 |               10 |        3181 |     28.358741196398324 |        0 |                   0 |          3181 |        28.13799203892083
Heap/INSERT                  |     7 |                7 |        1299 |     11.580636533832575 |        0 |                   0 |          1299 |        11.49049093321539
Transaction/COMMIT           |     3 |                3 |        1161 |     10.350361059106714 |        0 |                   0 |          1161 |       10.269792127377267
Storage/CREATE               |     3 |                3 |         126 |      1.123294998662744 |        0 |                   0 |           126 |       1.1145510835913313
Heap/INPLACE                 |     2 |                2 |         376 |      3.352054916644379 |        0 |                   0 |           376 |       3.3259619637328615
Heap2/PRUNE                  |     2 |                2 |         180 |     1.6047071409467772 |        0 |                   0 |           180 |        1.592215833701902
Standby/LOCK                 |     2 |                2 |          84 |     0.7488633324418293 |        0 |                   0 |            84 |       0.7430340557275542
Btree/DELETE                 |     1 |                1 |          60 |     0.5349023803155925 |        0 |                   0 |            60 |       0.5307386112339673
Standby/RUNNING_XACTS        |     1 |                1 |          50 |      0.445751983596327 |        0 |                   0 |            50 |      0.44228217602830605
Heap/DELETE                  |     1 |                1 |          54 |     0.4814121422840332 |        0 |                   0 |            54 |       0.4776647501105705
Heap/HOT_UPDATE              |     1 |                1 |          80 |     0.7132031737541232 |        0 |                   0 |            80 |       0.7076514816452897
Heap/INSERT+INIT             |     1 |                1 |          61 |      0.543817419987519 |        0 |                   0 |            61 |       0.5395842547545334
XLOG/FPI                     |     1 |                1 |          49 |     0.4368369439244005 |       88 |                 100 |           137 |       1.2118531623175586
(14 rows)

在这种情况下，显示按resource_manager 和 record_type分组的统计信息。此外，由于Btree索引占用WAL大小最大，但没有在SQL语句示例中定义任何btree索引，因此这些活动可能与pg_class的索引有关。这有助于提醒我们索引维护如何在数据库中产生工作负载，如果将未使用的索引从数据库中删除，将有助于提高性能。该函数的输出将有助于了解什么活动最能生成记录wal，并检测到一些异常或解释服务器行为。

CREATE操作

现在让我们关注resource_manager 和 record_type 列，它们分别显示了 wal 类型的一种分类和具体的 wal 记录类型。有关每个含义的更多详细信息，请参见：Postgres 源代码中的rmgrlist.h和rmgrdesc文件头文件。

Storage/CREATE组合意味着创建了一个对象，但在这种情况下，这些组合出现了 3 次，而我们的测试只写了一次。这怎么可能？

如果我们查看描述列，可以看到创建对象的路径和 OID，如果我们分析这些路径，我们可以看到以下内容：

SELECT
  relname,
  CASE 
    when relkind = 'r' then 'tab'
    when relkind = 'i' then 'idx'
    when relkind = 'S' then 'seq'
    when relkind = 't' then 'toast'
    when relkind = 'v' then 'view'
    when relkind = 'm' then 'matview'
    when relkind = 'c' then 'composite'
    when relkind = 'f' then 'F tab'
    when relkind = 'p' then 'part tab'
    when relkind = 'I' then 'part idx'
  END as object_type
FROM
    pg_class
  WHERE
    oid IN ('16415', '16418', '16419');
relname        | object_type 
----------------------+-------------
pg_toast_16415       | toast
pg_toast_16415_index | idx
my_tab               | tab
(3 rows)

注意：relkind 值可以在 pg_class 文档中找到

创建了具有相应索引的表和 TOAST 表，因此请记住，在幕后可能会发生许多对象的创建需要一些额外的数据来持久化。这适用于索引、TOAST 对象等实例，因此请注意某些对象可能会生成其他隐式对象，因此会产生一些额外的工作量。

事务个数

让我们看一下 xid 列，它代表事务编号。可以看到三个事务号747、748 和 749。这提醒我们，如果不指定事务的BEGIN和COMMIT/ROLLBACK块，Postgres是如何在事务中封装一个简单的SQL语句的。注意：在执行一些相关的 SQL 语句时，尽可能了解包括事务块（BEGIN…COMMIT/ROLLBACK）是有帮助的。包含一个事务的块可以避免浪费事务的 id，这最终将有助于达到环绕阈值限制并强制执行主动的 autovacuum。这种类型的 autovacuum 可能会直接影响数据库性能。此外，在每个事务结束时，可以看到一个Transaction/COMMIT组合和该事务结束的时间戳。