PgSQL · 答疑解惑 · RDS中的PostgreSQL备库延迟原因分析
最后更新于：2022-04-01 10:38:51
## 背景
在RDS环境中，多租户使用同一台主机是很常见的事情，为了隔离用户资源，有很多手段，例如使用虚拟机，或者CGROUP技术。以CGROUP为例，可以控制进程的CPU使用、内存使用、块设备的IOPS或者吞吐速率等资源使用。限制资源的好处是可以在共用的硬件层面为多个用户提供承诺的性能指标。当然这种方法也有一定的弊端，例如当用户需要运行消耗较多资源的SQL的时候，无法利用机器的空闲资源，因为它被限制住了。还有一些弊端可能导致RDS的不稳定，本文将展开讨论其中的弊端之一，资源限制是如何导致备库延迟的。
## 分析过程
创建一个实例，32G内存(确保测试时不被OOM)，1000GB存储空间，将块设备的读写IOPS都限制到200。
修改限制可以在控制台或者主机上操作，主机上操作举例：
获取postmaster进程号
~~~
$ps -ewf|grep pg468619
pg468619 24097 1 0 Jul29 ? 00:00:17 /path/to/postgres -D /path/to/data
~~~
查看这个进程所在的组
~~~
$cat /proc/24097/cgroup
3:memory:/rule3038
2:cpu:/rule3038
1:blkio:/rule3038
~~~
目前已限制在200
~~~
$cat /path/to/rule3038/blkio.throttle.read_iops_device
8:0 200
8:16 200
$cat /path/to/rds/rule3038/blkio.throttle.write_iops_device
8:0 200
8:16 200
~~~
如果没有限制，可以直接修改以上两个文件，或者使用cgset例如：
~~~
cgset -r blkio.throttle.write_iops_device='8:0 200' rule3038
cgset -r blkio.throttle.write_iops_device='8:16 200' rule3038
~~~
对应的块设备
~~~
$ll /dev/sda
brw-rw---- 1 root disk 8, 0 May 18 13:59 /dev/sda
$ll /dev/sdb
brw-rw---- 1 root disk 8, 16 Jul 31 07:45 /dev/sdb
~~~
接下来需要做的是创建测试用户，以及测试函数和测试表：
连接到数据库
~~~
$psql -p 3038 -U pg468619 postgres
~~~
创建测试用户
~~~
postgres=# create role digoal login encrypted password 'digoal';
postgres=# grant all on database postgres to digoal;
~~~
创建测试表，用于存储主节点插入XLOG的LSN以及备库接收、写、FLUSH、APPLY的XLOG LSN位置，以便计算主节点产生XLOG的速度和备库延迟的字节数。
~~~
postgres=# create table tbl_xlog_insert(id int,
sec numeric default EXTRACT(EPOCH from clock_timestamp()),
xlog_lsn text default pg_current_xlog_insert_location(),
sent_lsn pg_lsn,
write_lsn pg_lsn,
flush_lsn pg_lsn,
replay_lsn pg_lsn);
~~~
创建测试函数，目的是快速的产生大量XLOG，同时记录XLOG的位置到测试表。
~~~
postgres=# \c postgres postgres
postgres=# create or replace function f_test(int) returns void as $_$
declare
v_tbl name := 'tbl_'||pg_backend_pid();
ddl text := ' (id int8';
begin
set synchronous_commit=off;
execute 'DROP TABLE IF EXISTS '||v_tbl;
-- 创建一个201个字段的测试表.
for i in 1..200 loop
ddl := ddl||',c'||i||' int8 default 0';
end loop;
ddl := ddl||') ';
execute 'create table '||v_tbl||ddl||' with (autovacuum_enabled=off, toast.autovacuum_enabled=off)';
execute 'insert into '||v_tbl||' select generate_series(1,'||$1||')';
execute 'DROP TABLE IF EXISTS '||v_tbl;
-- 插入当前的XLOG位置, standby接收到的位置. 可能有一定的反馈延迟,延迟10毫秒
perform pg_sleep(0.01);
insert into tbl_xlog_insert(id, sent_lsn,write_lsn,flush_lsn,replay_lsn) select pg_backend_pid(), sent_location,write_location,flush_location,replay_location from pg_stat_replication limit 1;
end;
$_$ language plpgsql strict security definer;
postgres=# GRANT execute on function f_test(int) to digoal;
~~~
在测试机创建测试脚本
~~~
postgres@digoal-> cat test.sql
select f_test(5000);
~~~
测试时，使用1个连接就够了，太多了又会带来新的问题，心跳检测失败可能导致主备切换，这也是目前资源限制引起的一个问题，后面再来谈这个问题如何处理。
~~~
postgres@digoal-> pgbench -M prepared -n -r -f ./test.sql -c 1 -j 1 -t 100 -h digoal0001.pg.rds.aliyuncs.com -p 3999 -U digoal postgres
~~~
在主节点查询主库产生XLOG的速度，以及备库延迟的情况：
~~~
postgres=# select round(0.001*pg_xlog_location_diff((lead(xlog_lsn,1) over(order by sec))::pg_lsn,xlog_lsn::pg_lsn)/(case lead(sec,1) over(order by sec)-sec when 0 then 1 else lead(sec,1) over(order by sec)-sec end), 2)as gen_xlog_KBpsec,
round(pg_xlog_location_diff(xlog_lsn::pg_lsn,sent_lsn)/1024.0, 2) AS sent_xlog_delay_KB,
round(pg_xlog_location_diff(xlog_lsn::pg_lsn,write_lsn)/1024.0, 2) AS write_xlog_delay_KB,
round(pg_xlog_location_diff(xlog_lsn::pg_lsn,flush_lsn)/1024.0, 2) AS flush_xlog_delay_KB,
round(pg_xlog_location_diff(xlog_lsn::pg_lsn,replay_lsn)/1024.0, 2) AS replay_xlog_delay_KB
from tbl_xlog_insert where id=(select id from tbl_xlog_insert order by sec desc limit 1) order by sec;
gen_xlog_kbpsec | sent_xlog_delay_kb | write_xlog_delay_kb | flush_xlog_delay_kb | replay_xlog_delay_kb
-----------------+--------------------+---------------------+---------------------+----------------------
814.87 | 8616.37 | 8616.37 | 8616.37 | 8616.54
809.63 | 10752.44 | 13952.44 | 16896.44 | 16898.04
802.75 | 12747.91 | 14795.91 | 17227.91 | 17227.92
821.96 | 12173.92 | 16269.92 | 19981.92 | 23022.60
820.87 | 13167.77 | 17515.32 | 19799.77 | 23168.63
581.98 | 15177.93 | 19553.93 | 23009.93 | 26213.85
1320.19 | 12735.36 | 17087.36 | 20415.36 | 24112.03
818.03 | 17281.54 | 21761.54 | 25729.54 | 28560.27
808.66 | 17093.73 | 21445.73 | 25413.73 | 26377.87
. . . . .
. . . . .
. . . . .
. . . . .
806.56 | 79064.04 | 83544.04 | 87128.04 | 90281.66
804.10 | 82864.95 | 87472.95 | 87472.95 | 92209.77
802.53 | 84598.83 | 88310.83 | 91766.83 | 95275.68
598.90 | 82998.66 | 90038.66 | 90038.66 | 93495.39
1304.52 | 84704.81 | 89184.81 | 92768.81 | 92768.95
807.26 | 86847.66 | 91199.66 | 94527.66 | 97583.47
823.86 | 89209.00 | 93561.00 | 97785.00 | 97785.32
805.17 | 96967.23 | 101319.23 | 105287.23 | 108879.23
829.41 | 101531.95 | 105883.95 | 109979.95 | 113468.85
797.81 | 101999.23 | 106479.23 | 110447.23 | 110448.48
609.47 | 102789.51 | 107269.51 | 111109.51 | 114741.74
| 99381.25 | 103861.25 | 107573.25 | 111083.62
(100 rows)
~~~
XLOG产生速度约800KB/s, 由于XLOG盘的IOPS限制，导致STANDBY延迟不断增大。为了排除并不是网络延迟导致的延迟，我们可以使用systemtap跟踪wal sender、wal writter进程的IOPS以及wal sender进程的网络吞吐。
需要先安装kernel debuginfo，跟踪指定postgres wal writter进程，获取读写IOPS：
~~~
\# vi io.stp
global reads, writes, total_io
probe vfs.read.return {
reads[execname()] += 1
}
probe vfs.write.return {
writes[execname()] += 1
}
\# print every 1 seconds
probe timer.s(1) {
foreach (name in writes)
total_io[name] += writes[name]
foreach (name in reads)
total_io[name] += reads[name]
printf ("%16s\t%10s\t%10s\n", "Process", "SUM Read IO", "SUM Written IO")
foreach (name in total_io-)
printf("%16s\t%10d\t%10d\n", name,
reads[name], writes[name])
delete reads
delete writes
print("\n")
}
\# print total_io when exit
probe end {
foreach (name in total_io-)
printf("%16s\t%10d\t%10d\n", name,
reads[name], writes[name])
delete total_io
print("\n")
}
\# stap -vp 5 -DMAXSKIPPED=9999 -DSTP_NO_OVERLOAD -DMAXTRYLOCK=100 ./io.stp -x $pid
~~~
跟踪指定postgres wal sender进程，获取网络传输速率：
~~~
\# vi net.stp
global ifxmit, ifrecv
global ifmerged
// 定义3个全局变量, 分别用于存储传输,接收,以及合并数组;
// 传输和接收数组中存储统计信息;
// 合并数组存储网络接口上按照pid(), dev_name, execname(), uid()维度累加的传输和接收包个数.
probe netdev.transmit
{
ifxmit[pid(), dev_name, execname(), uid()] <<< length
}
// netdev.transmit 探针, 网络设备传输buffer时触发.
probe netdev.receive
{
ifrecv[pid(), dev_name, execname(), uid()] <<< length
}
// netdev.receive 探针, 从网络设备接收数据时触发.
function print_activity()
{
printf("%5s %5s %-7s %7s %7s %7s %7s %-15s\n",
"PID", "UID", "DEV", "XMIT_PK", "RECV_PK",
"XMIT_KB", "RECV_KB", "COMMAND")
foreach ([pid, dev, exec, uid] in ifrecv) {
ifmerged[pid, dev, exec, uid] += @count(ifrecv[pid,dev,exec,uid]);
}
foreach ([pid, dev, exec, uid] in ifxmit) {
ifmerged[pid, dev, exec, uid] += @count(ifxmit[pid,dev,exec,uid]);
}
// 按照倒序输出
foreach ([pid, dev, exec, uid] in ifmerged-) {
n_xmit = @count(ifxmit[pid, dev, exec, uid])
n_recv = @count(ifrecv[pid, dev, exec, uid])
printf("%5d %5d %-7s %7d %7d %7d %7d %-15s\n",
pid, uid, dev, n_xmit, n_recv,
n_xmit ? @sum(ifxmit[pid, dev, exec, uid])/1024 : 0,
n_recv ? @sum(ifrecv[pid, dev, exec, uid])/1024 : 0,
exec)
}
// 输出: pid, uid, 网络接口, 传输包数, 接收包数, 传输KB, 接收KB, command.
print("\n")
delete ifxmit
delete ifrecv
delete ifmerged
}
// print_activity 函数, 按照pid,dev,exec,uid维度, 根据网络接收和传输包数倒序输出.
// n_xmit ? @sum(ifxmit[pid, dev, exec, uid])/1024 : 0,
// n_recv ? @sum(ifrecv[pid, dev, exec, uid])/1024 : 0,
// 表示传输和接收的KB数.
// print_activity 函数的末尾清除三个全局变量的值. 下次调用时重新输出上一次输出以来的统计信息.
probe timer.s(1), end, error
{
print_activity()
}
// 每1秒调用一次print_activity .
\# stap -vp 5 -DMAXSKIPPED=9999 -DSTP_NO_OVERLOAD -DMAXTRYLOCK=100 ./io.stp -x $pid
~~~
因为生产上没有debuginfo的包，没有办法完成以上跟踪。不过为了验证不是网络原因导致的问题，还有其他手段。`sar -n DEV 1 100000`也可以查看网络传输。iotop则可以观察进程的IO，很遗憾生产上也没有iotop。
那么接下来，放开cgroup的限制，我们可以通过`sar -n DEV 1 100000`观察一下网络带宽：
主库和备库的postgres进程都从cgroup移除：
~~~
\#cat /proc/50511/cgroup
3:memory:/rule3008
2:cpu:/rule3008
1:blkio:/rule3008
\#cgdelete memory:/rule3008
\#cgdelete cpu:/rule3008
\#cgdelete blkio:/rule3008
$cat /proc/119876/cgroup
3:memory:/rule3090
2:cpu:/rule3090
1:blkio:/rule3090
\#cgdelete memory:/rule3090
\#cgdelete cpu:/rule3090
\#cgdelete blkio:/rule3090
~~~
目前的网络带宽是1GB：
~~~
\#ethtool eth0|grep Speed
Speed: 1000Mb/s
~~~
再次测试，我们可以观察到网络传输达到了1GB/8，约120MB/s：
~~~
01:54:24 PM IFACE rxpck/s txpck/s rxkB/s txkB/s rxcmp/s txcmp/s rxmcst/s
01:54:25 PM lo 132.29 132.29 29.42 29.42 0.00 0.00 0.00
01:54:25 PM eth0 85685.42 6495.83 125161.86 538.14 0.00 0.00 0.00
01:54:25 PM eth1 125.00 77.08 32.55 34.17 0.00 0.00 2.08
01:54:25 PM bond0 85808.33 6570.83 125192.78 572.14 0.00 0.00 2.08
01:54:25 PM IFACE rxpck/s txpck/s rxkB/s txkB/s rxcmp/s txcmp/s rxmcst/s
01:54:26 PM lo 125.00 125.00 28.50 28.50 0.00 0.00 0.00
01:54:26 PM eth0 85412.50 6509.38 124869.50 519.73 0.00 0.00 0.00
01:54:26 PM eth1 129.17 97.92 11.04 57.40 0.00 0.00 0.00
01:54:26 PM bond0 85544.79 6611.46 124883.69 577.44 0.00 0.00 0.00
~~~
当然，完全开放IOPS也有风险。如果网络带宽低于主节点产生WAL的速度，可能导致备库需要的WAL在主库WAL被快速回收，这种情况下，备库如果不能从任何地方获取到需要的XLOG，则备库会处于青黄不接的状态。我们需要考虑调整相应的wal keep segments，或者备库使用归档进行恢复，脱离青黄不接的状态。
以下是完全放开IOPS限制后带来的问题，由于写WAL速度超过了网络带宽120MB/S，达到了300MB/S，所以备库同样会延迟：
~~~
postgres=# select round(0.001*pg_xlog_location_diff((lead(xlog_lsn,1) over(order by sec))::pg_lsn,xlog_lsn::pg_lsn)/(case lead(sec,1) over(order by sec)-sec when 0 then 1 else lead(sec,1) over(order by sec)-sec end), 2)as gen_xlog_KBpsec,
round(pg_xlog_location_diff(xlog_lsn::pg_lsn,sent_lsn)/1024.0, 2) AS sent_xlog_delay_KB,
round(pg_xlog_location_diff(xlog_lsn::pg_lsn,write_lsn)/1024.0, 2) AS write_xlog_delay_KB,
round(pg_xlog_location_diff(xlog_lsn::pg_lsn,flush_lsn)/1024.0, 2) AS flush_xlog_delay_KB,
round(pg_xlog_location_diff(xlog_lsn::pg_lsn,replay_lsn)/1024.0, 2) AS replay_xlog_delay_KB
from tbl_xlog_insert where id=(select id from tbl_xlog_insert order by sec desc limit 1) order by sec;
gen_xlog_kbpsec | sent_xlog_delay_kb | write_xlog_delay_kb | flush_xlog_delay_kb | replay_xlog_delay_kb
-----------------+--------------------+---------------------+---------------------+----------------------
306692.66 | 2763682.05 | 2769058.05 | 2769058.05 | 2773902.84
310323.46 | 2821964.55 | 2826060.55 | 2826060.55 | 2830312.84
286290.82 | 2878171.34 | 2882267.34 | 2882267.34 | 2888606.55
308019.02 | 2933665.58 | 2937761.58 | 2937761.58 | 2941141.12
347211.31 | 2992420.60 | 2996516.60 | 2996516.60 | 3000172.73
339915.61 | 3049958.89 | 3054054.89 | 3054054.89 | 3060592.84
345896.39 | 3110687.52 | 3115295.52 | 3115295.52 | 3123686.84
326032.85 | 3169349.81 | 3174213.81 | 3174341.81 | 3176994.25
309214.90 | 3223985.07 | 3231409.07 | 3231409.07 | 3234051.52
335529.65 | 3273305.11 | 3277529.11 | 3277529.11 | 3286191.45
329873.46 | 3330912.32 | 3335008.32 | 3335008.32 | 3343094.45
293908.19 | 3386875.67 | 3392251.67 | 3392251.67 | 3398439.91
329390.57 | 3439531.98 | 3443627.98 | 3443627.98 | 3448171.41
~~~
当备库需要的XLOG在主库被覆盖后，备库无法获得对应的WAL，这种情况下，只能重新搭建备库，或者从归档获取需要的XLOG：
~~~
91812 2015-07-31 05:55:40 UTC 00000 LOG: started streaming WAL from primary at B/7A000000 on timeline 1
91812 2015-07-31 05:55:40 UTC XX000 FATAL: could not receive data from WAL stream: ERROR: requested WAL segment 000000010000000B0000007A has already been removed
91833 2015-07-31 05:55:45 UTC 00000 LOG: started streaming WAL from primary at B/7A000000 on timeline 1
91833 2015-07-31 05:55:45 UTC XX000 FATAL: could not receive data from WAL stream: ERROR: requested WAL segment 000000010000000B0000007A has already been removed
~~~
## 解决办法探讨
问题：
1. 限制XLOG盘的IOPS，在用户长时间临近IOPS限制的操作下，可能导致备库延迟，同时可能带来心跳超时的问题。
2. 如果不限制XLOG盘的IOPS，那么可能导致主节点产生WAL的速度过快，超出网卡的带宽（目前来看，换万兆网就可以解决这个问题），这样的话主库的XLOG可能会被覆盖掉，备库会无法获取需要的XLOG。
解决办法探讨：
1. 不限制XLOG盘的IOPS，同时使用万兆网卡。
2. 备库配置restore command，当主库的WAL被覆盖后，使用归档恢复。
## 参考
[红帽cgroup文档](https://access.redhat.com/documentation/en-US/Red_Hat_Enterprise_Linux/6/html/Resource_Management_Guide/index.html)
[systemtap文档](https://sourceware.org/systemtap/)