折磨许久的逻辑解码异常

1前言

这几天一直被业务方的逻辑解码异常所困扰，发布端是 PostgreSQL，订阅端是 Oracle，通过 DTS 不断抽取到 Oracle，但是每过一阵子，业务方就会反馈数据不一致了，walsender 进程好像被卡死了，解析速度特别慢。分析了两三天，终于有点眉目了。

2分析

由于当时的现场比较少，只能根据同事反馈的信息尝试分析一下，大致现象是：业务方反馈源端和订阅端数据不一致，DBA 进到库里查看发现 pg_stat_replication 的 write_lsn 和 send_lsn 推进速度缓慢，且发现 pg_replslot 目录下有大量的 xid-xxxxx-lsn-xxx.spill 文件，同时等待事件可以看到有 WalSenderWaitForWAL。

以上便是基本的现象，试着复盘一下。首先是 pg_replslot 目录下存在大量的 spill 文件，之前 PostgreSQL 大会上有过类似的分享，不过是子事务造成的

对应的复制槽目录下也存在了大量的 spill 文件，导致 walsender 卡死，但是根据排查，此例并没有使用到子事务，也没有使用带有异常捕获（EXCEPTION）的函数。这里我就不兜兜绕绕了，直接说结论。线上版本是 13，在此版本中，逻辑订阅引入了一个新的参数 logical_decoding_work_mem ，该参数用于控制逻辑解码过程中内存中可以存放的变更数量 👇🏻

Specifies the maximum amount of memory to be used by logical decoding, before some of the decoded changes are written to local disk. This limits the amount of memory used by logical streaming replication connections. It defaults to 64 megabytes (64MB). Since each replication connection only uses a single buffer of this size, and an installation normally doesn't have many such connections concurrently (as limited by max_wal_senders), it's safe to set this value significantly higher than work_mem, reducing the amount of decoded changes written to disk.

指定在将某些解码更改写入本地磁盘之前，逻辑解码要使用的最大内存量。这限制了逻辑流复制连接使用的内存量。它默认为 64 兆字节 (64MB)。由于每个复制连接仅使用此大小的单个缓冲区，并且实例通常不会并发许多此类连接（受 max_wal_senders 限制），因此将此值设置为显着高于 work_mem 是安全的，从而减少写入的解码更改量到磁盘。

在 13 以前，数据库只会为内存中的每个事务至多保留 4096 个更改 (max_changes_in_memory)。如果有一个非常冗长的大事务，其余的更改会作为溢出文件溢出到磁盘，也就是我们看到的那一些 spill 文件。如果每个变化都很大，甚至还有子事务的话，那么内存消耗很容易达到几个 GB。另一方面，如果变化非常小，但是却有太多的小变化，那么事务就会很长，溢出到磁盘，造成额外的 IO 开销，相关代码在 reorderbuffer.c 中

/*
 * Maximum number of changes kept in memory, per transaction. After that,
 * changes are spooled to disk.
 *
 * The current value should be sufficient to decode the entire transaction
 * without hitting disk in OLTP workloads, while starting to spool to disk in
 * other workloads reasonably fast.
 *
 * At some point in the future it probably makes sense to have a more elaborate
 * resource management here, but it's not entirely clear what that would look
 * like.
 */
int   logical_decoding_work_mem;
static const Size max_changes_in_memory = 4096; /* XXX for restore only */

不过在 13 版本之后，这块逻辑进行了优化，不再使用max_changes_in_memory (4096) 。相反，PostgreSQL 会跟踪所有事务的总内存使用量和单个事务的内存使用量，只有超过 logical_decoding_work_mem 此参数限制，缓冲区才会溢出到磁盘，并且只有消耗最多内存的最大事务才会成为溢出到磁盘的受害者。没错，选择受害者，溢出到磁盘这个操作变得更加聪明，会选择消耗内存最大的那个事务。

下面的注释写的很清楚，同时也提到了子事务的危害，子事务越多，遍历花费的时间就越多。

/*
 * Find the largest transaction (toplevel or subxact) to evict (spill to disk).
 *
 * XXX With many subtransactions this might be quite slow, because we'll have
 * to walk through all of them. There are some options how we could improve
 * that: (a) maintain some secondary structure with transactions sorted by
 * amount of changes, (b) not looking for the entirely largest transaction,
 * but e.g. for transaction using at least some fraction of the memory limit,
 * and (c) evicting multiple transactions at once, e.g. to free a given portion
 * of the memory limit (e.g. 50%).
 */
static ReorderBufferTXN *
ReorderBufferLargestTXN(ReorderBuffer *rb)
{
 HASH_SEQ_STATUS hash_seq;
 ReorderBufferTXNByIdEnt *ent;
 ReorderBufferTXN *largest = NULL;
 hash_seq_init(&hash_seq, rb->by_txn);
 while ((ent = hash_seq_search(&hash_seq)) != NULL)
 {
  ReorderBufferTXN *txn = ent->txn;
  /* if the current transaction is larger, remember it */
  if ((!largest) || (txn->size > largest->size))
   largest = txn;
 }
 Assert(largest);
 Assert(largest->size > 0);
 Assert(largest->size <= rb->size);
 return largest;
}

然后在 14 的版本里面进一步针对此进行了优化，没错就是我们所熟知的 streaming 接口，大幅降低大事务和长事务的复制延迟，当超过 logical_decoding_work_mem 时，便会考虑流式传输。但这并不意味着缓冲区永远不会溢出到磁盘。如果无法进行流式传输，则仍然可以选择溢出到磁盘。如果当前可用的信息不足以解码，就会发生这种情况。

至此我们简单分析清除了 spill 文件的来源——大事务，那让我们模拟一下，为了尽可能复现，我们也使用 13 版本，同时把 logical_decoding_work_mem 参数调到最小 64kB

postgres=# show logical_decoding_work_mem ;
 logical_decoding_work_mem 
---------------------------
 64kB
(1 row)
postgres=# begin;
BEGIN
postgres=*# select txid_current();
 txid_current 
--------------
          489
(1 row)
postgres=*# insert into t1 values(generate_series(1,1000));
INSERT 0 1000

然后磁盘上很快就可以看到溢出文件了

[postgres@xiongcc sub1]$ ls -lrth
total 140K
-rw------- 1 postgres postgres 136K Feb  9 16:43 xid-489-lsn-0-3000000.spill
-rw------- 1 postgres postgres  184 Feb  9 16:43 state

在代码里可以看到 debug2 级别就会输出到日志

/*
 * Spill data of a large transaction (and its subtransactions) to disk.
 */
static void
ReorderBufferSerializeTXN(ReorderBuffer *rb, ReorderBufferTXN *txn)
{
 dlist_iter subtxn_i;
 dlist_mutable_iter change_i;
 int   fd = -1;
 XLogSegNo curOpenSegNo = 0;
 Size  spilled = 0;
 Size  size = txn->size;
 elog(DEBUG2, "spill %u changes in XID %u to disk",
   (uint32) txn->nentries_mem, txn->xid);

调整下再观察下日志

2023-02-09 16:46:19.918 CST [16533] DEBUG:  serializing snapshot to pg_logical/snapshots/0-3AC9798.snap
2023-02-09 16:46:19.927 CST [16533] DEBUG:  got new restart lsn 0/320D868 at 0/3AC9798
2023-02-09 16:46:19.927 CST [16533] DEBUG:  sending replication keepalive
2023-02-09 16:46:19.927 CST [16533] DEBUG:  write 0/3AC97D0 flush 0/3AC97D0 apply 0/3AC97D0 reply_time 2023-02-09 16:46:19.927248+08
2023-02-09 16:46:19.931 CST [16533] DEBUG:  updated xmin: 0 restart: 1
2023-02-09 16:46:20.720 CST [16533] DEBUG:  spill 497 changes in XID 489 to disk
2023-02-09 16:46:20.722 CST [16533] DEBUG:  spill 497 changes in XID 489 to disk
2023-02-09 16:46:20.722 CST [16533] DEBUG:  sending replication keepalive
2023-02-09 16:46:20.723 CST [16533] DEBUG:  write 0/3AD7FF8 flush 0/3AD7FF8 apply 0/3AD7FF8 reply_time 2023-02-09 16:46:20.722979+08
2023-02-09 16:46:21.725 CST [16533] DEBUG:  spill 497 changes in XID 489 to disk
2023-02-09 16:46:21.727 CST [16533] DEBUG:  spill 497 changes in XID 489 to disk
2023-02-09 16:46:21.728 CST [16533] DEBUG:  sending replication keepalive
2023-02-09 16:46:21.729 CST [16533] DEBUG:  write 0/3AE7FF8 flush 0/3AE7FF8 apply 0/3AE7FF8 reply_time 2023-02-09 16:46:21.729096+08

日志里很清晰，489 这个事务，每次溢出 497 条变更，同时可以看到 serializing snapshot to pg_logical/snapshots/0-3AC9798.snap，这个我在之前的文章中已经进行过分析，复制一下

这个快照里面记录了一些必要的信息，比如

• xmin/xmax/xip_list
• 快照开始时达到一致性状态的LSN，start_decoding_at
• 子事务的修改信息
• 系统表元组xmin，因为逻辑解码依赖系统表元组的可见性，某个事务的修改要对其他事务可见
• ...

在逻辑解码的过程中，下面这个SnapBuild就会一直不断被更新，因此也会涉及到脏数据。

那再模拟一下多个并发大事务，此处就用函数来模拟，因为函数整体是作为一个"原子"

postgres=# create or replace function mytest() returns void
as $$ 
begin
 for i in 0..1000000000 loop
  insert into t1 values(i);
 end loop;
end;
$$ language plpgsql;
CREATE FUNCTION

然后用 pgbench 模拟，pgbench -f bench.sql -j 10 -c 2 -T 300 ，同时另外一个窗口持续观察，watch -n 1 ls -lrth，几乎一瞬间就可以看到一堆溢出到磁盘的文件 👇🏻

-rw------- 1 postgres postgres 3.2M Feb  9 17:05 xid-513-lsn-0-16000000.spill
-rw------- 1 postgres postgres 3.3M Feb  9 17:05 xid-512-lsn-0-16000000.spill
-rw------- 1 postgres postgres  18M Feb  9 17:05 xid-512-lsn-0-17000000.spill
-rw------- 1 postgres postgres  18M Feb  9 17:05 xid-513-lsn-0-17000000.spill
-rw------- 1 postgres postgres  18M Feb  9 17:05 xid-512-lsn-0-18000000.spill
-rw------- 1 postgres postgres  18M Feb  9 17:05 xid-513-lsn-0-18000000.spill
-rw------- 1 postgres postgres  18M Feb  9 17:05 xid-513-lsn-0-19000000.spill
-rw------- 1 postgres postgres  18M Feb  9 17:05 xid-512-lsn-0-19000000.spill
-rw------- 1 postgres postgres  18M Feb  9 17:05 xid-512-lsn-0-1A000000.spill
-rw------- 1 postgres postgres  18M Feb  9 17:05 xid-513-lsn-0-1A000000.spill
-rw------- 1 postgres postgres  18M Feb  9 17:05 xid-513-lsn-0-1B000000.spill
-rw------- 1 postgres postgres  18M Feb  9 17:05 xid-512-lsn-0-1B000000.spill
-rw------- 1 postgres postgres  18M Feb  9 17:05 xid-512-lsn-0-1C000000.spill
-rw------- 1 postgres postgres  18M Feb  9 17:05 xid-513-lsn-0-1C000000.spill
-rw------- 1 postgres postgres  18M Feb  9 17:05 xid-513-lsn-0-1D000000.spill
-rw------- 1 postgres postgres  18M Feb  9 17:05 xid-512-lsn-0-1D000000.spill
-rw------- 1 postgres postgres  18M Feb  9 17:05 xid-512-lsn-0-1E000000.spill
-rw------- 1 postgres postgres  18M Feb  9 17:05 xid-513-lsn-0-1E000000.spill
-rw------- 1 postgres postgres  18M Feb  9 17:05 xid-512-lsn-0-1F000000.spill
-rw------- 1 postgres postgres  18M Feb  9 17:05 xid-513-lsn-0-1F000000.spill
-rw------- 1 postgres postgres  184 Feb  9 17:05 state
-rw------- 1 postgres postgres  18M Feb  9 17:05 xid-512-lsn-0-20000000.spill
-rw------- 1 postgres postgres  18M Feb  9 17:05 xid-513-lsn-0-20000000.spill
...

随着事务提交或回滚，这些文件就会被回收。在压测的同时去观察等待事件，可以看到也出现了 WalSenderWaitForWAL ，并且还出现了 ReorderBufferWrite，那么这两个等待事件是什么意思？

WalSenderWaitForWAL：Waiting for WAL to be flushed in WAL sender process.

ReorderBufferWrite：Waiting for a write during reorder buffer management.

     wait_event      | wait_event_type 
---------------------+-----------------
 LogicalLauncherMain | Activity
 AutoVacuumMain      | Activity
                     | 
 ReorderBufferWrite  | IO       ---👈🏻在这里
                     | 
 ClientRead          | Client
                     | 
 BgWriterMain        | Activity
 CheckpointerMain    | Activity
 WalWriterMain       | Activity
(10 rows)
Thu 09 Feb 2023 05:29:14 PM CST (every 1s)
     wait_event      | wait_event_type 
---------------------+-----------------
 LogicalLauncherMain | Activity
 AutoVacuumMain      | Activity
                     | 
 WalSenderWaitForWAL | Client     ---👈🏻在这里
                     | 
 ClientRead          | Client
                     | 
 BgWriterMain        | Activity
 CheckpointerMain    | Activity
 WalWriterMain       | Activity
(10 rows)

搜一下代码，对应的等待事件包括

• Client 类的 WAIT_EVENT_WAL_SENDER_WAIT_WAL
• IO 类的 ReorderBufferWrite

  /*
   * Sleep until something happens or we time out.  Also wait for the
   * socket becoming writable, if there's still pending output.
   * Otherwise we might sit on sendable output data while waiting for
   * new WAL to be generated.  (But if we have nothing to send, we don't
   * want to wake on socket-writable.)
   */
   /* 
   睡眠直到有事情发生或我们超时。 如果仍有待处理的输出，还要等待套接字变得可写。
   否则我们可能会等待生成新的 WAL 时等待可发送的输出数据。(但是如果我们没有任
   何东西要发送，我们不想在socket-writable上醒来。)
  */
  sleeptime = WalSndComputeSleeptime(GetCurrentTimestamp());
  wakeEvents = WL_SOCKET_READABLE;
  if (pq_is_send_pending())
   wakeEvents |= WL_SOCKET_WRITEABLE;
  WalSndWait(wakeEvents, sleeptime, WAIT_EVENT_WAL_SENDER_WAIT_WAL);
 }

至于 ReorderBufferWrite，Waiting for a write during reorder buffer management. 回顾一下我之前写过的逻辑解码原理

逻辑复制也通过walsender实现，walsender不停地读取WAL日志，会对每一条WAL日志记录都进行解析，将解析出的元组按照事务进行分组（保存进ReorderBuffer)，并按照事务的开始时间进行排序。在事务提交时，会对提交事务在ReorderBuffer中的所有信息使用相应的plugin进行解码，并将解码后的逻辑日志发送给备机或者接收工具（例如pg_recvlogical）。对应到前面的例子，一个事务横跨了多个WAL，所以需要从事务最开始保留到事务提交所在的WAL才能确保解析是正确的。

由于同一个事务的WAL日志是不连续的，并且可能横跨多个WAL（如本文中的案例），而逻辑解码要求同一个事务的日志按顺序相邻，因此会借助ReorderBuffer结构体来保存这些信息，同时用ReorderBufferTXN标识每一个事务（xid和TXN进行映射），在事务提交时，借助decode plugin对元组进行逻辑解码，比如自带的test_decoding、decoder_raw等等，按插件自己定制解析后输出逻辑解析成品，然后同一个ReorderBufferTXN中的操作会全部发送给订阅端。

所以这个等待事件也不难理解，就是在正常的解码过程中。另外在测试的过程中，可能会看到 pg_stat_replication 中 write_lsn 比 sent_lsn 小得多，不难理解，看这几个字段的意思就清楚了

• Last write-ahead log location sent on this connection，发布端 wal record flush 到磁盘后，发送给了订阅端
• Last write-ahead log location written to disk by this standby server，订阅端调用了 write 接口写盘
• Last write-ahead log location flushed to disk by this standby server，订阅端调用了 fsync 接口刷盘

并且逻辑复制是异步的：对于异步复制，只通知 walsender 进程，就返回 commit，walsender 再异步去发送

A different setting might be appropriate when doing synchronous logical replication. The logical replication workers report the positions of writes and flushes to the publisher, and when using synchronous replication, the publisher will wait for the actual flush. This means that setting synchronous_commit for the subscriber to off when the subscription is used for synchronous replication might increase the latency for COMMIT on the publisher. In this scenario, it can be advantageous to set synchronous_commit to local or higher.

至此，此案例基本复现七七八八分析明白了，没错，又双叒叕是大事务。既然知道了罪魁祸首，去故障时间点排查下事务的情况，也就是出现数据不一致的点（全天日志约 7GB，很大）

[postgres@xiongcc ~]$ cat postgresql-02-01.csv | grep -i 'begin' | wc -l
171485
[postgres@xiongcc ~]$ cat postgresql-02-01.csv | egrep '^2023-02-01 09:' | grep -i 'begin' | wc -l
10847
[postgres@xiongcc ~]$ cat postgresql-02-01.csv | egrep '^2023-02-01 09:10' | grep -i 'begin' | wc -l
196

可以看到，9 点一个小时有 10000 多条 begin，开了 1W+ 个事务，9:10 分这个点就有 200 个 begin，每个事务都做了满满一屏幕的操作，甚至一个屏幕都打印不全，才显式了 39%，用 shift + 4 翻到这一行的末尾，终端右下角会告诉你这一行有多长，一行 14734 个字符，真是一个长的不行的 SQL。然后我去搜索了一下 AWR ，发现这条 SQL 整天跑了七八万次！光是 9.10 ~ 9.15 就跑了2000多次

可想而知，那个点溢出到磁盘的文件会有多少，随时都有可能出问题。

3小结

长事务的危害真的太多了，为什么会被称为 DBKiller 是有原因的。回到这个案例，由于是13版本，优化措施也很有限

1. 和开发 battle，推动开发将事务拆小
2. 继续增大 logical_decoding_work_mem，但是治标不治本，最大内存可能会到 max_wal_senders * logical_decoding_work_mem，要小心 OOM

xiongcc，公众号：PostgreSQL学徒从实际案例聊聊逻辑解码

4参考

https://blog.anayrat.info/en/2018/03/10/logical-replication-internals/

https://www.percona.com/blog/logical-replication-decoding-improvements-in-postgresql-13-and-14/

http://blog.itpub.net/6906/viewspace-2639281/

https://billtian.github.io/digoal.blog/2016/11/07/01.html