[译]Postgres15-新特性-利用pg_walinspect对WAL事件进行debug
[译]Postgres15-新特性-利用pg_walinspect对WAL事件进行debug
利用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组合和该事务结束的时间戳。
结论
新扩展提供了所有活动的有用信息，使PG内部正确工作成为可能，并帮助我们更多地了解PG的工作原理。允许我们仅通过使用SQL语句就能了解一些预期行为和其他不为人知的行为。例如索引维护活动的权重。将来，该扩展也许可以帮助我们审计和分析数据库工作流并产生漂亮有趣的报告。
原文
https://www.ongres.com/blog/debugging-postgres-wal-events-with-pg_walinspect/
本文分享自 yanzongshuaiDBA 微信公众号，前往查看
如有侵权，请联系 cloudcommunity@tencent.com 删除。
本文参与 腾讯云自媒体分享计划 ，欢迎热爱写作的你一起参与！