1.背景
项目中，业务反馈说插入的数据不能及时查看到。于是查看pg_stat_replication视图，发现主备之间的replay_lag延迟很大，平均15分钟左右的延迟，导致目前业务看到的数据还是15分钟以前的数据，亟需解决。
2.定位
业务使用的是TBase，TBase的架构是CN + DN + GTM的这种经典架构
业务整体延迟情况类似如下，并且replay_lag持续上升，在备机查看进程可以看到如下:
postgres: startup process recovering 000000010000000800000075 waiting
目前TBase采用的强同步，synchronous_commit为on，也就是事务提交需要等到备库接收到WAL日志并且flush到磁盘，但并没有reply，对于查询来说还是属于不可见的状态，但PostgreSQL自身收到WAL再回放WAL的速度是很快的。在一般的PostgreSQL流复制场景下，如果主库不是很忙并且备库硬件资源充分，备库和主库的延迟都在毫秒级别。为了应对这种业务场景，PostgreSQL还提供synchronous_commit = remote_apply来保证备库接收到WAL日志，flush到磁盘并且进行reply，这样对于查询就可见了。不过这种会严重影响写性能，这个参数较on平均写入性能会下降30%左右，由于项目对QPS的要求十分高，不支持这么调整，所以只能从其他方面来优化。
3.优化
既然回放有延迟，那就是回放的时候发生了冲突导致的延迟。日志中可以看到大量的FATAL,40001,"terminating connection due to conflict with recovery","User query might have needed to see row versions that must be removed.","In a moment you should be able to reconnect to the database and repeat your command."
先从max_standby_streaming_delay查起，这个参数在TBase里面默认调整到了30min(单机PostgreSQL是30s)，通常会将一些执行时间较长的分析任务、统计SQL跑在备库上。在备库上执行长时间的查询，由于涉及的记录有可能在主库上被更新或删除，主库上对更新或删除数据的老版本进行vacuum后，从库上也会执行这个操作，从而与从库上的当前查询产生冲突。这个参数就指定了遇到这种冲突时的最大回放WAL的延迟。理论上在达到30min的时候，查询就会被cancel掉。在TBase里面这个值调整到这么大，有待商榷。目前将这个值调整到了10分钟。
分析完延迟的产生原因后，得分析如何缓解这个冲突，从前面分析得知，是由于PostgreSQL的MVCC机制，行版本冲突导致的延迟，max_standby_streaming_delay可以一定程度上地缓解。
除此之外，PostgreSQL还提供hot_standby_feedback参数，设置hot_standby_feedback参数之后备库会定期向主库通知最小活跃事务id(xmin)，PostgreSQL的MVCC机制简单来说，每一个Query开启的时候获取一个快照，快照理论上是某个时间点正在运行的事务列表，就跟相机拍摄按下的那一瞬间获取到的状态一样，快照由这样一个序列构成：xmin:xmax:xip_list：
|
testdb=# SELECT txid_current_snapshot(); txid_current_snapshot ----------------------- 100:104:100,102 (1 row) |
xmin：最早的状态仍为active的事务txid，所有比它更早的事务(txid
xmax：获取快照时第一个尚未分配的xid，所有txid>=xmax的事务在获取快照时尚未启动，因此其结果对当前事务不可见。
xip_list：获取快照时，所有active事务的txid列表，该列表仅包含[xmin,xmax)范围内的活跃事务txid
具体总结可以参照interdb，简单列一下
(这里假设图片中表示的事务都已经提交)图片上面的三条数据中，xmin都是有值的，xmax都是没值的，这意味着这三个数据被插入进来后，还未被删除。和快照中的xmin，xmax和Running进行对比，30小于快照中的xmin，已经提交了，因此这条数据是可见的。50在Running列表中，还在执行中，因此不可见(注意第二张图，IF t_xmin = current_txid， return visible，大多数情况下都不可见，除非是事务自身，也就是说50这个事务获取了这个快照，50事务进行了插入但没提交，当然对于自己来说也可见)，110大于xmax，对于当前快照来说仍还未提交，也不可见。
(这里假设图片中表示的事务都已经提交)图片下面的数据中，xmin和xmax都有值，这意味着数据在被插入后，已经被某些事务标记为删除了。判断Tuple是否可见的规则就是两条，xmin已提交，xmax未提交，便是可见的。和快照中的数据做对比，xmin都是30，小于快照中的xmin 40。xmax 80，小于快照中的xmax 100，Running列表中没有，所以表示这个事务已经提交了，因此，这个数据便已经被删除了，不可见。第二行中的75，正在Running，因此它是可见的(当然，也是和上面类似，假如也是自身事务进行了删除但没提交，当然也已删除不可见)。第三行的120大于快照中的xmax 100，此事务对于当前快照被提交，对于当前查询来说仍然可见。因此知道了大概的原理之后，hot_standby_feedback也就能理解了，定期向主库通知最小活跃事务id(xmin)，因为vacuum里的逻辑
|
/* * Deleter committed, but perhaps it was recent enough that some open * transactions could still see the tuple. */ if (!TransactionIdPrecedes(HeapTupleHeaderGetRawXmax(tuple), OldestXmin)) return HEAPTUPLE_RECENTLY_DEAD; /* Otherwise, it's dead and removable */ return HEAPTUPLE_DEAD; } |
该函数计算当前tuple的xmax是否大于或等于OldestXmin。xmax是删除这个tuple的事务ID，而OldestXmin由GetOldestXmin函数计算，是所有活跃事务的ID，以及所有事务的xmin 组成的集合中最小的事务ID。所有ID大于这个OldestXmin的事务，都是“新近”开启的事务，其他事务可能需要读取这个旧版本用于查询，所以不能物理删除，则返回HEAPTUPLE_RECENTLY_DEAD，保留此tuple。换句话说，就是产生垃圾tuple的事务号，通常在为垃圾tuple的头信息中的xmax版本号大于或等于vacuum开启时数据库中最小的(backend_xmin, backend_xid)，这条垃圾tuple就不能被回收，因此备库发回来的xmin，可以让主库vacuum不去清理那些xmax大于xmin的这些行。简单来说就是定时“告诉”主库，备库仍然需要的行版本，让主库在vacuum的时候手下留情。当备机上执行查询的时候，会通过设置backend_xmin影响主机的元组可见性判断，从而主机不会vacuum清理相关元组。
这个参数看似可以解决问题，但是还是有几点弊端：
1)备库定时发送xmin给主库，但是网络本身就是一件“不太可靠”的东西，hot_standby_feedback and vacuum_defer_cleanup_age provide protection against relevant rows being removed by vacuum, but the former provides no protection during any time period when the standby is not connected，延迟、抖动、链路长度太长、跨IDC等，这些都是不可抗拒的因素，最终导致发送xmin的速度变“慢”了，主库相应收到的速度也变“慢”了，再加上主库的更新频率特别高，所以冲突还是不可避免的；
2)假如备库开启的是repeatable read和serializable级别的事务，整个snapshot会持续到SQL结束，假如SQL持续200s，也就是备库发回的xmin会一直不变持续200s，那这个期间主库上需要保持的垃圾行版本是特别多的，本该需要清理的垃圾版本却堆积了；
3)walreceive和walsender也是进程，流复制通过这两个进程进行传输WAL日志流，但是断断续续的抽风谁也控制不了，于是一些非预期的vacuum可能发生在walreceiver进程重连的期间之内，也就可能会导致查询冲突的情况。这种情况可以通过复制槽来缓解，即使进程断了也不影响。复制槽就不多介绍了，可以参考我之前的文章。
4)第四点也是最容易被忽视的一点，之前在定位锁冲突的过程中，发现startup回放进程会获取一个AccessExclusive Lock，这一点很是诧异，于是通过如下SQL抓取阻塞进程select pid,pg_blocking_pids(pid),wait_event_type,query from pg_stat_activity where wait_event_type = 'Lock' and pid!=pg_backend_pid();
可以看到，被64985这个进程阻塞了，pg_blocking_pids()就是获取阻塞当前pid的进程，看一下是什么在作祟，可以看到，是startup回放进程
startup回放进程想要在表204614上获取一个AccessExclusive Lock，但是加锁失败，也就是上图中的granted = 'f'。
问题来了，为什么startup进程会需要获取AccessExclusive Lock？很容易想到的一点是，回放了DDL。在昨天也遇到了延迟的问题，然后通过排查，发现在昨天上午9点的时候另外一个DBA做了create index的操作，用以优化慢SQL(当然这是一个十分不规范的操作，后面已经复盘。因为上线后任何一个变更都需要走流程，更何况是这种DDL语句，8级锁，影响层面是十分巨大的，生产环境重中之重，任何一个不起眼的操作可能会导致业务停服等严重后果)，当时认为是这个导致的。就算下午发现还有Access Exclusive的时候还是悻悻地认为是产品BUG，或许是BUG导致的遗留DDL产生的排它锁。
但在今天，又遇到了这个情况，又在获取Access Exclusive，经过昨天的复盘之后，可以确认没有任何DDL操作了，那这里为什么还会有这个Access Exclusive，深入分析回顾了一下，既然冲突的根因是vacuum，那就追一下vacuum的逻辑，普通vacuum我们熟知的就是清理垃圾tuple回收空间，更新fsm，以供下次插入，但是并不能回收空间，这是vacuum full做的动作；但是在一种情况下，会获取Access Exclusive，The standard form of VACUUM removes dead row versions in tables and indexes and marks the space available for future reuse. However, it will not return the space to the operating system, except in the special case where one or more pages at the end of a table become entirely free and an exclusive table lock can be easily obtained. 也就是说只有一种情况下，即回收的页处于存储数据的文件(一张表对应一个或多个文件)尾部，并且页内没有事务可见的tuple(即整个页都可以删除)时，会做truncate操作，这一步骤会获取AccessExclusive Lock，把尾部的这些页统一从文件中删除，文件大小和表所占空间随之减少。
既然这样的话，那就有迹可寻了，去备机看一下日志，果然如此
其中的DN主上的日志：
|
2020-10-14 12:12:41.892 CST,,,290956,coord(0,0),,5f867ab9.4708c,coord(0,0),1,,2020-10-14 12:12:41 CST,1363/4673,0,LOG,00000,"truncate cutoffpage 88283",,,,,,,,,"" 2020-10-14 13:02:18.001 CST,,,174752,coord(0,0),,5f8685b2.2aaa0,coord(0,0),1,,2020-10-14 12:59:30 CST,1415/7797,0,LOG,00000,"truncate cutoffpage 102712",,,,,,,,,"" 2020-10-14 15:25:07.641 CST,,,292077,coord(0,0),,5f86a7d3.474ed,coord(0,0),1,,2020-10-14 15:25:07 CST,1419/13138,0,LOG,00000,"truncate cutoffpage 114312",,,,,,,,,"" 2020-10-14 17:35:51.811 CST,,,147400,coord(0,0),,5f86c262.23fc8,coord(0,0),1,,2020-10-14 17:18:26 CST,772/25092,0,LOG,00000,"truncate cutoffpage 123123",,,,,,,,,"" 2020-10-14 18:40:50.745 CST,,,280011,coord(0,0),,5f86d5b2.445cb,coord(0,0),1,,2020-10-14 18:40:50 CST,1313/17890,0,LOG,00000,"truncate cutoffpage 155417",,,,,,,,,"" |
查看WAL日志可以抓到
|
pg_waldump 000000010000023B0000008C|grep 248928315 rmgr: Storage len (rec/tot): 46/ 46, tx: 248928315, lsn: 23B/8C7FAB90, prev 23B/8C7F9240, desc:TRUNCATE base/198140/204929 to 173 blocks flags 7 rmgr: Heap len (rec/tot): 619/ 619, tx: 248928315, lsn: 23B/8CC60858, prev 23B/8CC60680, desc: INPLACE off 6, blkref #0: rel 1663/198140/1259 blk 236 |
另外，在排查的过程中，还发现在truncate CLOG，CLOG中存储着事务的状态，当冻结发生的时候，会删除一些不需要的CLOG，因为小于冻结事务的事务已经可见了。
综上所述，排它锁的获取情况还是有很多种的。
|
pg_waldump ../pg_wal/000000010000027200000043 | grep TRUN rmgr: CLOG len (rec/tot): 38/ 38, tx: 0, lsn: 272/43400DD0, prev 272/43400B90, desc: TRUNCATE page 3288; oldestXact 107767786 rmgr: CommitTs len (rec/tot): 34/ 34, tx: 0, lsn: 272/4340B7B8, prev 272/4340B308, desc: TRUNCATE pageno 236852, oldestXid 107767786 |
相应的DN备上的日志
|
2020-10-14 12:12:41.892 CST,,,34190,coord(0,0),,5f85fe86.858e,coord(0,0),47495,,2020-10-14 03:22:46 CST,1/0,0,LOG,00000,"redo committs: truncate latest page number 88283",,,,,"WAL redo at 21C/63C6B458 for CommitTs/TRUNCATE: pageno 88283, oldestXid 40168947",,,,"" 2020-10-14 13:02:17.999 CST,,,34190,coord(0,0),,5f85fe86.858e,coord(0,0),55863,,2020-10-14 03:22:46 CST,1/0,0,LOG,00000,"redo committs: truncate latest page number 102712",,,,,"WAL redo at 231/245C1C78 for CommitTs/TRUNCATE: pageno 102712, oldestXid 46733969",,,,"" 2020-10-14 15:30:00.744 CST,,,34190,coord(0,0),,5f85fe86.858e,coord(0,0),82129,,2020-10-14 03:22:46 CST,1/0,0,LOG,00000,"redo committs: truncate latest page number 114312",,,,,"WAL redo at 236/C0942150 for CommitTs/TRUNCATE: pageno 114312, oldestXid 52012193",,,,"" 2020-10-14 17:35:51.812 CST,,,34190,coord(0,0),,5f85fe86.858e,coord(0,0),108733,,2020-10-14 03:22:46 CST,1/0,0,LOG,00000,"redo committs: truncate latest page number 123123",,,,,"WAL redo at 248/19C73C28 for CommitTs/TRUNCATE: pageno 123123, oldestXid 56020968",,,,"" 2020-10-14 18:40:50.746 CST,,,34190,coord(0,0),,5f85fe86.858e,coord(0,0),122837,,2020-10-14 03:22:46 CST,1/0,0,LOG,00000,"redo committs: truncate latest page number 155417",,,,,"WAL redo at 24B/6A0CC908 for CommitTs/TRUNCATE: pageno 155417, oldestXid 70714822",,,,"" |
这里便可以看到，AccessExclusive Lock阻塞着，导致后面的AccessShare Lock都得排队。但是这种机制，并没有什么参数可以控制这个，因为在单机PostgreSQL中，我认为vacuum这个获取排它锁truncate页面并归还给操作系统，对于表膨胀来说是有益的，尤其是对于刚入门的小白，和磁盘吃紧的情况下，可以一定程度的缓解表膨胀。但是在分布式的场景下，尤其是大并发，大量更新的场景下，这个的弊端也就出来了。毕竟是一个排它锁，尤其是涉及到大量数据重分布的时候，这个锁还会带来什么更严重的影响，尚不清楚，但不难想象会导致锁的竞争更加复杂和严重。
另外，在昨天研究的过程中，发现某些lag达到了30min以上，也就是说max_standby_streaming_delay好像未生效，后面进一步分析，发现是死锁，分布式场景下，死锁较单机会出现的更加频繁，因为涉及到多个节点的交互，再加上一旦数据重分布，这个逻辑会更加复杂。后面在加上了lock_timeout之后，今天便没有见到这个情况了。这个后面需要加强意识，DDL、DML等操作必须设置锁等待，可以防止堵塞所有其他与该DDL锁对象相关的QUERY。
上面探讨的vacuum会获取AccessExclusive Lock，会对备上的查询有一定的影响，但是也没有参数可以控制这个机制，是否就无解了呢？其实可以变相解决，既然是vacuum导致的，那就给vacuum动一下手术，降低vacuum的频率。在以往单机PostgreSQL中，往往都是想加快vacuum的频率，vacuum_cost_limit会往大了调，autovacuum_vacuum_scale_factor和autovacuum_vacuum_threshold往小了调(前提是IO要好，没有瓶颈，不然会导致vacuum频繁触发，占据过多资源，vacuum本身就是一件很耗费资源的事)。
但是在目前这个场景下，就可以把autovacuum_vacuum_threshold和autovacuum_vacuum_scale_factor往大了调，这样就会降低vacuum的速度，这样可以一定程度上降低冲突和锁，坏处就是表膨胀，需要关注表的膨胀率。为了不影响整个实例，最后选择表级调整，也就是alter table xxx set ( autovacuum_vacuum_threshold = xxx)和lter table xxx set ( autovacuum_vacuum_scale_factor= xxx),而对于autovacuum_vacuum_cost_limit和autovacuum_vacuum_cost_delay就不建议调了，这个值不太好调，毕竟成本cost和到达成本限制后延迟多少，不好拿捏，一般默认10ms都足够多了。autovacuum_vacuum_cost_limit在SSD的机器上可以调到10000。
除此之外，也将这个更新特别频繁的表建成了分区表，不过得要求业务使用的时候能够分区裁剪，同时还调整了fillfactor，以更好的利用HOT技术，降低索引的额外IO，这里就不再赘述了。
另外一点需要的注意的是vacuum_defer_cleanup_age这个参数，Similarly, hot_standby_feedback and vacuum_defer_cleanup_age provide protection against relevant rows being removed by vacuum, but the former provides no protection during any time period when the standby is not connected, and the latter often needs to be set to a high value to provide adequate protection. vacuum_defer_cleanup_age指定vacuum延迟清理死亡元组的事务数，vacuum会延迟清除无效的记录，延迟的事务个数通过vacuum_defer_cleanup_age进行设置。即vacuum和vacuum full操作不会立即清理刚刚被删除元组。这个参数在设置了hot_standby_feedback之后，也没有太多必要调整这个值了，延迟清理在大并发的情况，调整多少合适是一个十分难取舍的，并且这个参数也不太好设定阈值。调整这个参数的代价也是很大的，第一点很容易想到，延迟清理会导致主库膨胀，因为垃圾版本要延迟若干个事务后才能被回收；第二重复扫描垃圾版本，重复耗费垃圾回收进程的CPU资源，因为垃圾tuple的数量会一直处于超过回收阈值的状态，从而autovacuum launch不断唤醒worker进行回收动作，特别是当主库的 autovacuum_naptime值很小，同时autovacuum_vacuum_scale_factor和autovacuum_vacuum_threshold很小的值时，尤为明显。第三点也可以想象，如果期间产生大量update，垃圾版本会堆积很多，假如vacuum_defer_cleanup_age的值为5，又是5个大事务，1个事务更新1万条，然后在事务提交后，爆炸性地回收，产生大量的WAL日志，从而造成WAL的写IO尖刺。
当然针对于这个vacuum的潜在隐患，在PostgreSQL 9.6以前，当vacuum回收垃圾时，遇到垃圾记录的xmax大于数据库中现存的最早未提交事务xmin时，不会对其进行回收。因此当数据库中存在很久为结束的事务时，可能会导致数据库膨胀。为此9.6以后引入了old_snapshot_threshold，强制删除为过老的事务快照保留的dead元组。这会导致长事务读取已被删除tuple时出错。snapshot too old报错通常出现在非常大的SQL，同时读取的数据块在不断的变化。
与vacuum_defer_cleanup_age类似的，还有一个recovery_min_apply_delay，这个参数主要用在延迟备库的场景下，指定这个值，备库在收到WAL日志后，并不立即重做，而是等待这个时间后再进行回放，注意备库依然是及时收到WAL日志的，只是延迟了回放，但是在目前这个案例中，这个值也不太好调整。还有一点，假如synchronous_commit = remote_apply的话，每一个事务提交都需要等待这个值指定的大小，这个也是一个雷，需要特别注意。而且这个值还会影响hot_standby_feedback，hot_standby_feedback will be delayed by use of this feature which could lead to bloat on the master; use both together with care.
最后一点，假如业务量能够评估的话，把查询放在主上也不失为一个好办法，这样就不会有延迟。不过这个风险极大，不建议放到主上，毕竟某一个DN主挂了，业务也就瘫痪了。不建议趟这个雷。
4.总结
1．虽然表级调整了vacuum的参数，但需要时刻关注膨胀率，如何调整一个合适的值，以控制表的膨胀是一个需要持续观察的事情。
2．基于PostgreSQL的分布式和单机PostgreSQL，还是有很多差异的，分布式较单机本身就更加复杂，承载的业务量和数据量也会更大
3．参数的调整，也需要应对场景灵活调整，各个场景下，参数可以灵活多变。比如此案例，调整vacuum相关参数之后，延迟平稳。
4．任何时候，长事务都是需要特别关注的点，长事务在什么数据库中都是DB killer。