案例|一步步分析逻辑解码hang

Joyann♪

于 2024-03-25 21:09:06 发布

阅读量987

点赞数 10

分类专栏： PostgreSQL生产案例文章标签： postgresql 数据库

本文链接：https://blog.csdn.net/u011312513/article/details/137025527

版权

PostgreSQL生产案例专栏收录该内容

1 篇文章 0 订阅

订阅专栏

（一）案例背景

一次同事反馈PG逻辑解码过程中出现hang，业务受阻的生产故障，第一次碰到这个问题，通过阅读源码10分钟定位并给出解决方案。但在后续又双叒出现相同的问题，而同事不清楚什么情况下适用这套解决方案，为什么类似的场景下同样的解决方案不灵验。
我在想：授人以鱼不如授人以渔，于是有了这篇文章。

（二）案例分析

故事发生在五一节后。当时接到DBA同事反馈生产环境有个复制槽状态是正常的，节前创建不久后就一直没消费，源端无新增数据，节后业务上班发现调度异常，业务受阻。由于相关同事第一次碰到这个问题，没有解决思路，“重启大法”都于事无补，故邀我一起分析分析。

一般生产异常，个人习惯是先看OS和DB版本，鸟瞰全局再分析，本次案例不涉及全局分析，故不赘述，仅列出版本信息，如下：
在这里插入图片描述

既然是逻辑解码异常，那么我们就来看看，复制槽处于什么状态，都在做些什么？堵塞在哪里？

1）复制槽状态简析

查看异常复制槽的基础情况：

借助pg_replication_slots和pg_stat_replication视图

Tips: PG 14在逻辑解码监控管理层面新增了较多视图，有兴趣的可以自行查阅官网

SQL样例如下：

SELECT pid,usename,s.database,slot_name,s.plugin,s.slot_type,client_addr salve_addr, state, 
pg_size_pretty(pg_wal_lsn_diff(sent_lsn, pg_current_wal_lsn())) sent_lag, 
pg_size_pretty(pg_wal_lsn_diff(pg_current_wal_lsn(), replay_lsn))  apply_lag, 
sync_state ,s.restart_lsn,s.wal_status
 FROM pg_stat_replication r 
 JOIN pg_replication_slots s 
 ON r.pid=s.active_pid AND s.slot_name='jslot01';
 
-- 结果样例:
-- [ RECORD 1 ]---------------------------------------
pid         | 123456
usename     | dtsuser
database    | joyann
slot_name   | jslot01
plugin      | wal2json
slot_type   | logical
salve_addr  | 172.168.12.34
state       | catchup
sent_lag    | -37 GB
apply_lag   | [null]
sync_state  | async
restart_lsn | 28/A5268
wal_status  | extended

从上可以看出，该数据槽处于catchup状态，即表示wal sender进程连接的standby备节点正在追赶primary主节点，在PG中，replication从startup启动到streaming最终追赶上中间的状态都定义为：catchup。

在PG 13中，pg_replication_slots视图主要更新点为如下2点：
在这里插入图片描述
其中，max_slot_wal_keep_size为PG 13新增的参数，为了防止复制槽异常而导致WAL日志不断堆积，可以设置该参数作为因复制槽导致的WAL日志堆积的上限。生产环境设置需要权衡利弊。

在这里插入图片描述
该字段为PG 13新增字段，案例中为extended，意味着max_wal_size已超出，但因复制槽的影响因素促使WAL日志仍保留。

Tips: 可以通过pg_stat_replication视图观察WAL sender进程具体压力，例如:

master主服务器端查看pg_wal_lsn_diff(sent_lsn, pg_current_wal_lsn())的值，从而反映master端承担的压力。利用master主节点的sent_lsn和standby备服务器端的pg_last_wal_receive_lsn()反映standby端压力。

standby端可利用如下SQL查看延时情况：

PG 10以前：

SELECT CASE WHEN pg_last_xlog_receive_location() = pg_last_xlog_replay_location() THEN 0 ELSE EXTRACT (EPOCH FROM now() - pg_last_xact_replay_timestamp()) END AS log_delay;

PG 10以后：

SELECT CASE WHEN pg_last_wal_receive_lsn() = pg_last_wal_replay_lsn() THEN 0 ELSE EXTRACT (EPOCH FROM now() - pg_last_xact_replay_timestamp()) END AS log_delay;

2）堆栈分析

Tips: 在生产故障/异常分析处理过程中，可以利用pstack、strace、gdb、perf等分析堆栈信息，尝试去理解代码的设计与用意，从而加深理解，形成良性循环。

[postgres@joyann:1302 ~]$pstack 123456
#0  hash_seq_search (status=status@entry=0x7fff742fd470) at dynahash.c:1441
#1  0x000000000071c756 in ReorderBufferLargestTXN (rb=<optimized out>) at reorderbuffer.c:2340
#2  ReorderBufferCheckMemoryLimit (rb=0x160f3a8) at reorderbuffer.c:2390
#3  ReorderBufferQueueChange (rb=0x160f3a8, xid=xid@entry=344511, lsn=183354435968, change=<optimized out>) at reorderbuffer.c:649
#4  0x000000000071e6cf in ReorderBufferAddNewCommandId (rb=<optimized out>, xid=xid@entry=344511, lsn=<optimized out>, cid=<optimized out>) at reorderbuffer.c:2131
#5  0x00000000007201d0 in SnapBuildProcessNewCid (builder=builder@entry=0x16ec638, xid=xid@entry=344511, lsn=<optimized out>, xlrec=<optimized out>) at snapbuild.c:795
#6  0x00000000007131d4 in DecodeHeap2Op (buf=0x7fff742fd500, ctx=0x16a92b8) at decode.c:382
#7  LogicalDecodingProcessRecord (ctx=0x16a92b8, record=<optimized out>) at decode.c:122
#8  0x0000000000733662 in XLogSendLogical () at walsender.c:2885
#9  0x0000000000735942 in WalSndLoop (send_data=send_data@entry=0x733620 <XLogSendLogical>) at walsender.c:2287
#10 0x0000000000736692 in StartLogicalReplication (cmd=0x160ec68) at walsender.c:1213
#11 exec_replication_command (cmd_string=cmd_string@entry=0x15e1b08 "START_REPLICATION SLOT myslot01 LOGICAL 28/A5268 (\"pretty-print\" '1', \"include-xids\" '1', \"include-timestamp\" '1', \"add-tables\" 'public.lin_joyann,"...) at walsender.c:1640
#12 0x0000000000774e91 in PostgresMain (argc=<optimized out>, argv=argv@entry=0x16134a8, dbname=0x1613308 "jytest13", username=<optimized out>) at postgres.c:4325
#13 0x0000000000485989 in BackendRun (port=<optimized out>, port=<optimized out>) at postmaster.c:4526
#14 BackendStartup (port=0x160b410) at postmaster.c:4210
#15 ServerLoop () at postmaster.c:1739
#16 0x0000000000702f08 in PostmasterMain (argc=argc@entry=3, argv=argv@entry=0x15dc4c0) at postmaster.c:1412
#17 0x000000000048660a in main (argc=3, argv=0x15dc4c0) at main.c:210

从最后一行main函数开始，自下而上的查阅堆栈信息。通常我们会比较关注前面几行。

因此，我们先看下ReorderBufferCheckMemoryLimit的逻辑。

ReorderBufferCheckMemoryLimit

/*
   检查是否达到了 logical_decoding_work_mem 限制，如果是，则一次选择最大的（子）事务来逐出并将其更改溢出到磁盘，直到我们达到内存限制以下。
   在这一点上，我们选择事务直到达到内存限制，但我们也可能采用更精细的驱逐策略——例如驱逐足够多的事务以释放内存限制的某些部分（例如 50%）。
 */
static void
ReorderBufferCheckMemoryLimit(ReorderBuffer *rb)
{
  ReorderBufferTXN *txn;

  /* 如果我们没有超过内存限制就退出 */
  if (rb->size < logical_decoding_work_mem * 1024L)
    return;

  /*
   循环直到我们达到内存限制。有人可能会认为，仅通过驱逐最大的（子）事务，
   我们就会基于所选事务至少与最近的更改一样大（这导致我们超过内存限制）的假设而受到内存限制。
   但是，这不是真的，因为用户可以在最近的更改之前将logical_decoding_work_mem 减少到一个较小的值。
   */
  while (rb->size >= logical_decoding_work_mem * 1024L)
  {
    /*
    选择最大的事务（或子事务）并通过将其序列化到磁盘将其从内存中逐出。
     */
    txn = ReorderBufferLargestTXN(rb);

    ReorderBufferSerializeTXN(rb, txn);

    /*
    驱逐后，事务在内存中应该没有条目，并且应该使用 0 字节进行更改。
     */
    Assert(txn->size == 0);
    Assert(txn->nentries_mem == 0);
  }

  /* 现在应当在内存限制之下*/
  Assert(rb->size < logical_decoding_work_mem * 1024L);
}

ReorderBufferCheckMemoryLimit 会判断当前事务量的大小是否大于logical_decoding_work_mem参数的限制。所以，并不是堆栈走了ReorderBufferCheckMemoryLimit->ReorderBufferLargestTXN就要考虑logical_decoding_work_mem调整参数的。

合理情况下，若真的超过了logical_decoding_work_mem大小，正常的调用顺序应该是：

ReorderBufferCheckMemoryLimit检查确认超过了参数限制

->ReorderBufferLargestTXN找到占用内存最多的最大的事务

->ReorderBufferSerializeTXN序列化到磁盘->…。

如果堆栈长时间一直卡在ReorderBufferLargestTXN函数内，这种情况是不大正常的。我们先来看看这个函数：

ReorderBufferLargestTXN

/*
  找到要驱逐（溢出到磁盘）的最大事务（顶层或 subxact）。
  对于许多子事务，这可能会很慢，因为我们必须遍历所有子事务。
  有一些我们可以改进的选项：
 （a）维护一些二级结构，事务按更改量排序，
 （b）不寻找完全最大的事务，但例如对于使用至少一部分内存限制的事务，
  以及 (c) 一次驱逐多个事务，例如释放内存限制的指定部分（例如 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 ((!largest) || (txn->size > largest->size))
      largest = txn;
  }

  Assert(largest);
  Assert(largest->size > 0);
  Assert(largest->size <= rb->size);

  return largest;
}

在逻辑解码的过程中，会对WAL日志进行解析。

解析后以ReorderBufferTXN,ReorderBufferChange的形式存储在ReorderBuffer中。

你可以简单的理解为每个ReoderBufferTXN都代表一个事务，其中事务ID是唯一标识符。

ReorderBufferLargestTXN目的是为了找到ReorderBuffer中最大的TXN，其中，hash_seq_init初始化和hash_seq_search检索只是利用hash表的特性设计的结构。

3）strace

对上述两个函数有一定了解后，我们重点放到当解析后存在在ReorderBuffer中保存的事务占用内存超过logical_decoding_work_mem，会尝试对找到最大事务量的事务进行驱逐溢出到磁盘的行为本身。

借助strace命令，我们一共验证驱逐溢出到磁盘的行为：

[postgres@joyann:1302 ~]$strace -e trace=all -T -tt -p 118792
strace:Process 118792 attached
16:51:03.979046 open("pg_replslot/jslot01/xid-891608270-1sn-7c3-C8000000.spi¹l",O_WRONLYIO_CREATIO_APPEND,0600)=17 <0.00021O>
16:51:03.979448 write(17,
"e\1\0\0\0\0\0\0\310^\214\317\303\7\0\0\0\0\0\0\0\0\0\0\3704D*\0\0\0\0"...,357)=357
<0.000029>
16:51:03.979520 close(17)=0 <0.000016>
16:51:03.979561 recvfrom(9,0x7ffccacd17ff,1,0,NULL,NULL)=-1 EAGAIN(Resourcetemporarily unavailable)<0.000012>
16:51:03.979615 recvfrom(9,0x7ffccacd17ff,1,0,NULL,NULL)=-1 EAGAIN(Resourcetemporarily unavailable)<0.000021>
16:51:03.979672 ---SIGUSR1 {si_signo=SIGUSR1,si_code=SI_USER,si_pid=177867,
si_uid=6001}---
16:51:03.979702 rt_sigreturn({mask=[]})=-1 EAGAIN(Resource temporarily unavailable)
<0.000012?
16:51:03.979741 recvfrom(9,0x7ffccacd17ff,1,0,NULL,NULL)=-1 EAGAIN(Resourcetemporarily unavailable)<0.000011>
16:51:03.979776 recvfrom(9,0x7ffccacd17ff,1,0,NULL,NULL)=-1 EAGAIN(Resourcetemporarily unavailable)<0.000010>
16:51:03.979810 recvfrom(9,0x7ffccacd17ff,1,0,NULL,NULL)=-1 EAGAIN(Resourcetemporarily unavailable)<0.000010>

通过strace我们可以看到后台在不断做溢出到磁盘的行为(上述仅截取一部分)，其中open的路径对应的是：PG data_dir目录下的->pg_replslot–>jslot01(当前复制槽的名字)。

Tips: 例如上述的：xid-891608270-lsn-7c3-c8000000.spill文件，我们可以通过lsn：7c3/c8000000，使用

select pg_walfile_name('7C3/C8000000');

查看到对应的WAL文件名，找到对应的walfile文件后，结合pg_waldump命令和事务号XID：891608270定位到具体在执行的内容。

通过解析pg_waldump我们可以看到大量的WAL日志里面记录的都是同一个事务，这个事务很大，跨越众多WAL日志。既是长事务又是ReoderBuffer中最大事务量的，后台不断地找到ta又驱逐ta。

4）快速处理方案

由于业务催得急，为了降低业务影响。我们把关注点放到了ReorderBufferCheckMemoryLimit这段代码中的：

  /* 如果我们没有超过内存限制就退出 */
  if (rb->size < logical_decoding_work_mem * 1024L)
    return;
  /*

最简单、最快速的解决方案，必然是加大logical_decoding_work_mem参数，让这个长事务可以顺利通过这一内存。当然，参数调整后需要：

psql -c 'select pg_reload_conf();'
-- 或者
pg_ctl -D $PGDATA reload

即：调整参数不用重启，reload配置就行。

关于logical_decoding_work_mem参数，可控制逻辑解码在溢出到磁盘之前可使用的内存量。详可见官方说明：

https://www.postgresql.org/docs/13/release-13.html

本案例中：

将logical_decoding_work_mem从默认的64MB调整为512MB，调整参数并reload生效后，DBA同事观察到数据库lag在逐步减少，复制槽的目标端也开始正常消费，问题关闭。注意调整时，要看下实际可用内存，避免参数设置过大。

具体要调整多大，需要评估ReorderBuffer中保留的最大事务占用内存量。

调整参数后，查看堆栈，看堆栈的内容是否正常走到：

ReorderBufferSerializeChange序列化到磁盘的步骤。

（三）案例思考

理性看待logical_decoding_work_mem参数，PG 13推出这个参数很大程度上避免了低版本复制槽占用过多内存导致内存使用率过高甚至OOM的情况。本意是对历史场景的优化，但在13版本中对于长事务不断溢出到磁盘的做法，考虑不算周到。

在PG 14版本支持stream流式传输ReorderBuffer给目标订阅端，能流式传输的均走stream，只要例如当前信息不足以解码等情况下，会溢出到磁盘。

有兴趣可以阅读相关commit

https://git.postgresql.org/gitweb/?p=postgresql.git;a=commit;h=45fdc9738b

对于PG 13及以上版本，建议生产环境可以根据不同的内存规格(如果对业务逻辑解码使用情况有一定了解可按需设置)，设置不同的logical_decoding_work_mem参数的值，而非默认值。从而，获取更好的运维效果，降低生产影响。

后话：

如果有任何需要指正/指教/交流的，可以关注微信公众号《PostgreSQL手记》后台评论，大家一起学习~

在这里插入图片描述

Joyann♪

关注

10
点赞
踩
25

收藏

觉得还不错? 一键收藏
0
评论
案例|一步步分析逻辑解码hang

一步步讲解生产案例逻辑解码hang的分析过程，解决方案，堆栈源码分析等
复制链接

扫一扫

专栏目录