0

一次PG的wal日志异常增长---1

pg那些事 2021-03-25
206

起因:主备同步停止;

故障发生时间:未知,需自己判断

检查备库日志:

    cd $PGDATA/pg_log
    2020-10-21 03:11:33.699 CST,,,31184,,5f8739af.79d0,2,,2020-10-15 01:47:27 CST,,0,FATAL,XX000,"could not receive data from WAL stream: ERROR: requested WAL segment 000000030000058500000015 has already been removed",,,,,,,,,""

    发现是在03:00发生,检查此时段的wal日大小:

      [postgres@kbj-db-1 5434arch]$ export LANG=en_US
      [postgres@kbj-db-1 5434arch]$ ls -lht |grep -i "Oct 21 03"|wc -l
      3245

      每个wal日志大小为16MB;算一下:

        [postgres@kbj-db-1 5434arch]$ echo 3245*16|bc
        51920

        一个小时产生了50G的归档日志

        查询hist_snap

          select * from hist_snap  where begin_interval_time >'2020-10-21 02:00:00' and begin_interval_time<'2020-10-21 04:00:00'
          select total_time,mean_time,max_time,min_time,shared_blks_written,
          query from hist_statements where id>1525 and id<1528 order by max_time desc limit 5;


          发现有一个1355秒的vacuum操作;

          查询pormetheus,对应的事务和备库产生的延迟均对得上;

          基本可以得出结论是vacuum产生了大量的日志写入;查看wal内容

            cd $PGDATA/../5434arch/
            pg_waldump 000000030000058500000015
            rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn: 585/15001840, prev 585/14FFF800, desc: VISIBLE cutoff xid 0 flags 2, blkref #0: rel 1663/528
            518/597054 fork vm blk 7, blkref #1: rel 1663/528518/597054 blk 234045
            rmgr: Heap2 len (rec/tot): 57/ 8153, tx: 0, lsn: 585/15001880, prev 585/15001840, desc: FREEZE_PAGE cutoff xid 100575562 ntuples 48, blkref #
            0: rel 1663/528518/597054 blk 234046 FPW
            rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn: 585/15003878, prev 585/15001880, desc: VISIBLE cutoff xid 0 flags 2, blkref #0: rel 1663/528
            518/597054 fork vm blk 7, blkref #1: rel 1663/528518/597054 blk 234046
            rmgr: Heap2 len (rec/tot): 57/ 8161, tx: 0, lsn: 585/150038B8, prev 585/15003878, desc: FREEZE_PAGE cutoff xid 100575562 ntuples 49, blkref #
            0: rel 1663/528518/597054 blk 234047 FPW

            查询对应的wal文件

              SELECT pg_walfile_name('585/15001840');
              000000030000058500000015

              这里列一下pg_waldump的最基本用法(--help挺好使):

              列出所有的资源:

                pg_waldump --rmgr=list

                其他用法:

                  -s, --start=RECPTR     start reading at WAL location RECPTR
                  -z, --stats[=record] show statistics instead of records
                  -b, --bkp-details output detailed information about backup blocks

                  抽取其中一个日志分析:

                    [postgres@kbj-db-1 5434arch]$ pg_waldump  000000030000058500000015 -z
                    Type N (%) Record size (%) FPI size (%) Combined size (%)
                    ---- - --- ----------- --- -------- --- ------------- ---
                    XLOG 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                    Transaction 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                    Storage 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                    CLOG 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                    Database 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                    Tablespace 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                    MultiXact 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                    RelMap 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                    Standby 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                    Heap2 4052 (100.00) 235010 (100.00) 16463156 (100.00) 16698166 (100.00)
                    Heap 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                    Btree 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                    Hash 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                    Gin 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                    Gist 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                    Sequence 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                    SPGist 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                    BRIN 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                    CommitTs 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                    ReplicationOrigin 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                    Generic 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                    LogicalMessage 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                    -------- -------- -------- --------
                    Total 4052 235010 [1.41%] 16463156 [98.59%] 16698166 [100%]

                    说明:

                    heap2(RM_HEAP2_ID)是数据库对heap的修改产生的wal记录,如下为heap2类型的wal子类型

                      #define XLOG_HEAP2_REWRITE      0x00
                      #define XLOG_HEAP2_CLEAN 0x10
                      #define XLOG_HEAP2_FREEZE_PAGE 0x20
                      #define XLOG_HEAP2_CLEANUP_INFO 0x30
                      #define XLOG_HEAP2_VISIBLE 0x40
                      #define XLOG_HEAP2_MULTI_INSERT 0x50
                      #define XLOG_HEAP2_LOCK_UPDATED 0x60
                      #define XLOG_HEAP2_NEW_CID 0x70

                      查看日志的详细信息

                        [postgres@kbj-db-1 5434arch]$ pg_waldump  000000030000058500000015 -b |more
                        rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn: 585/15001840, prev 585/14FFF800, desc: VISIBLE cutoff xid 0 flags 2
                        blkref #0: rel 1663/528518/597054 fork vm blk 7
                        blkref #1: rel 1663/528518/597054 fork main blk 234045
                        rmgr: Heap2 len (rec/tot): 57/ 8153, tx: 0, lsn: 585/15001880, prev 585/15001840, desc: FREEZE_PAGE cutoff xid 100575562 ntuples 48
                        blkref #0: rel 1663/528518/597054 fork main blk 234046 (FPW); hole: offset: 360, length: 96

                        对应的OID信息如下:

                          oid2name
                          All databases:
                          Oid Database Name Tablespace
                          -----------------------------------
                          528518 ktcc pg_default
                          528519 loghistory pg_default
                          12371 postgres pg_default
                          12370 template0 pg_default
                          1 template1 pg_default

                           取对应的表名:

                            $ oid2name  -f 597054  -p 5434
                            pg_waldump  000000030000058300000004 -b|grep -i blkref|awk '{print $4}'|sort |uniq -c|head

                            接着发现了几个,发现每个得出来的都不大一样;

                            分析这个时段的日志产生的所有记录:

                              $ ls -l |grep "Oct 21 03:"|head
                              -rw-r----- 1 postgres ssl-cert 16777216 Oct 21 03:00 000000030000058300000004
                              -rw-r----- 1 postgres ssl-cert 16777216 Oct 21 03:00 000000030000058300000005


                              $ ls -l |grep "Oct 21 03:"|tail
                              -rw-r----- 1 postgres ssl-cert 16777216 Oct 21 03:22 000000030000058F000000A7
                              -rw-r----- 1 postgres ssl-cert 16777216 Oct 21 03:22 000000030000058F000000A8
                              $ pg_waldump 000000030000058300000004 000000030000058F000000AF -z
                              Type N (%) Record size (%) FPI size (%) Combined size (%)
                              ---- - --- ----------- --- -------- --- ------------- ---
                              XLOG 130319 ( 0.97) 6385973 ( 0.81) 976443856 ( 1.83) 982829829 ( 1.81)
                              Transaction 819 ( 0.01) 227929 ( 0.03) 0 ( 0.00) 227929 ( 0.00)
                              Storage 1 ( 0.00) 46 ( 0.00) 0 ( 0.00) 46 ( 0.00)
                              CLOG 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                              Database 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                              Tablespace 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                              MultiXact 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                              RelMap 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                              Standby 1169 ( 0.01) 151523 ( 0.02) 0 ( 0.00) 151523 ( 0.00)
                              Heap2 12846701 ( 96.07) 749820917 ( 95.11) 50966197544 ( 95.42) 51716018461 ( 95.42)
                              Heap 24732 ( 0.18) 9471142 ( 1.20) 30043476 ( 0.06) 39514618 ( 0.07)
                              Btree 368412 ( 2.76) 22296213 ( 2.83) 1439264060 ( 2.69) 1461560273 ( 2.70)
                              Hash 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                              Gin 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                              Gist 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                              Sequence 12 ( 0.00) 1188 ( 0.00) 0 ( 0.00) 1188 ( 0.00)
                              SPGist 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                              BRIN 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                              CommitTs 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                              ReplicationOrigin 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                              Generic 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                              LogicalMessage 0 ( 0.00) 0 ( 0.00) 0 ( 0.00) 0 ( 0.00)
                              -------- -------- -------- --------
                              Total 13372165 788354931 [1.45%] 53411948936 [98.55%] 54200303867 [100%]

                              查看更详细的分析结果

                                $ pg_waldump  --stats=record 000000030000058300000004 000000030000058F000000AF |more
                                Type N (%) Record size (%) FPI size (%) Combined size (%)
                                ---- - --- ----------- --- -------- --- ------------- ---
                                XLOG/CHECKPOINT_ONLINE 6 ( 0.00) 636 ( 0.00) 0 ( 0.00) 636 ( 0.00)
                                XLOG/FPI_FOR_HINT 130311 ( 0.97) 6385239 ( 0.81) 976427472 ( 1.83) 982812711 ( 1.81)
                                XLOG/FPI 2 ( 0.00) 98 ( 0.00) 16384 ( 0.00) 16482 ( 0.00)
                                Transaction/COMMIT 175 ( 0.00) 5950 ( 0.00) 0 ( 0.00) 5950 ( 0.00)
                                Transaction/COMMIT 644 ( 0.00) 221979 ( 0.03) 0 ( 0.00) 221979 ( 0.00)
                                Storage/TRUNCATE 1 ( 0.00) 46 ( 0.00) 0 ( 0.00) 46 ( 0.00)
                                Standby/LOCK 1 ( 0.00) 42 ( 0.00) 0 ( 0.00) 42 ( 0.00)
                                Standby/RUNNING_XACTS 116 ( 0.00) 5832 ( 0.00) 0 ( 0.00) 5832 ( 0.00)
                                Standby/INVALIDATIONS 1052 ( 0.01) 145649 ( 0.02) 0 ( 0.00) 145649 ( 0.00)
                                Heap2/CLEAN 270919 ( 2.03) 17026768 ( 2.16) 1304920668 ( 2.44) 1321947436 ( 2.44)
                                Heap2/FREEZE_PAGE 6250882 ( 46.75) 359430085 ( 45.59) 49363105736 ( 92.42) 49722535821 ( 91.74)
                                Heap2/CLEANUP_INFO 163 ( 0.00) 6846 ( 0.00) 0 ( 0.00) 6846 ( 0.00)
                                Heap2/VISIBLE 6324737 ( 47.30) 373357218 ( 47.36) 298171140 ( 0.56) 671528358 ( 1.24)
                                Heap/INSERT 3638 ( 0.03) 3329613 ( 0.42) 1167640 ( 0.00) 4497253 ( 0.01)
                                Heap/DELETE 2481 ( 0.02) 136584 ( 0.02) 3002808 ( 0.01) 3139392 ( 0.01)
                                Heap/UPDATE 2700 ( 0.02) 2096656 ( 0.27) 3134812 ( 0.01) 5231468 ( 0.01)
                                Heap/HOT_UPDATE 9123 ( 0.07) 3164413 ( 0.40) 12923268 ( 0.02) 16087681 ( 0.03)
                                Heap/LOCK 4439 ( 0.03) 245871 ( 0.03) 7020988 ( 0.01) 7266859 ( 0.01)
                                Heap/INPLACE 2259 ( 0.02) 407568 ( 0.05) 2793960 ( 0.01) 3201528 ( 0.01)
                                Heap/INSERT+INIT 83 ( 0.00) 87685 ( 0.01) 0 ( 0.00) 87685 ( 0.00)
                                Heap/UPDATE+INIT 9 ( 0.00) 2752 ( 0.00) 0 ( 0.00) 2752 ( 0.00)
                                Btree/INSERT_LEAF 10774 ( 0.08) 680119 ( 0.09) 5860984 ( 0.01) 6541103 ( 0.01)
                                Btree/INSERT_UPPER 17 ( 0.00) 1070 ( 0.00) 64928 ( 0.00) 65998 ( 0.00)
                                Btree/SPLIT_L 8 ( 0.00) 28396 ( 0.00) 55420 ( 0.00) 83816 ( 0.00)
                                Btree/SPLIT_R 9 ( 0.00) 12227 ( 0.00) 3880 ( 0.00) 16107 ( 0.00)
                                Btree/DELETE 8 ( 0.00) 628 ( 0.00) 48940 ( 0.00) 49568 ( 0.00)
                                Btree/UNLINK_PAGE 4830 ( 0.04) 440009 ( 0.06) 22696248 ( 0.04) 23136257 ( 0.04)
                                Btree/MARK_PAGE_HALFDEAD 4816 ( 0.04) 358914 ( 0.05) 2597664 ( 0.00) 2956578 ( 0.01)
                                Btree/VACUUM 346860 ( 2.59) 20692220 ( 2.62) 1407935996 ( 2.64) 1428628216 ( 2.64)
                                Btree/REUSE_PAGE 7 ( 0.00) 322 ( 0.00) 0 ( 0.00) 322 ( 0.00)
                                Btree/META_CLEANUP 1083 ( 0.01) 82308 ( 0.01) 0 ( 0.00) 82308 ( 0.00)
                                Sequence/LOG 12 ( 0.00) 1188 ( 0.00) 0 ( 0.00) 1188 ( 0.00)
                                -------- -------- -------- --------
                                Total 13372165 788354931 [1.45%] 53411948936 [98.55%] 54200303867 [100%]

                                补充说明一下:

                                Type列

                                前部分是wal类型的分类,后部分是具体的wal日志类型,举个例子在Heap这种分类下,有INSERT,UPDATE,DELETE等wal类型。详情大家可以参考源码的rmgrlist.h

                                N列

                                表示某种wal类型出现的次数,如图中,出现了6250882 Heap2/FREEZE_PAGE 。N列后面的百分比列表示这种wal类型个数的比例,如6250882 /13372165                     ≈46.74%。

                                Record size列、FPI size列、Combined size列

                                表示某种wal类型的所占用的总长度在Combined size列显示,其中FPI数据的长度在FPI size列中,非FPI数据的长度在Record size列中。然后后面是他们各自所占的百分比。

                                注:FPI是指在一个wal记录中的一个page页的备份。

                                可以看出重点在,其中又以第一个为绝对占比,产生了49722535821(49GB)的量:

                                  Type                                           N      (%)          Record size      (%)             FPI size      (%)        Combined size      (%)
                                  Heap2/FREEZE_PAGE 6250882 ( 46.75) 359430085 ( 45.59) 49363105736 ( 92.42) 49722535821 ( 91.74)
                                  Heap2/VISIBLE 6324737 ( 47.30) 373357218 ( 47.36) 298171140 ( 0.56) 671528358 ( 1.24)

                                  copy归档到另外一盘分析(主要防止分析时把数据库数据盘IO占满)

                                    ls -l |grep "Oct 21 03:"|awk '{ print $NF}'|xargs -i cp {} ~/backup/arch

                                    再次分析,取出占比最大的表:

                                      $ pg_waldump  000000030000058300000004 000000030000058F000000AF |awk -F ,  '{print $NF}'| awk '{ print $4 }'|sort |uniq -c|sort -nr|head 
                                      1505450 1663/528518/914595
                                      1048485 1663/528518/532196
                                      750172 1663/528518/532192
                                      740411 1663/528518/532189
                                      694152 1663/528518/532197
                                      635545 1663/528518/532205
                                      600411 1663/528518/597054
                                      567829 1663/528518/532193
                                      474891 1663/528518/547740
                                      oid2name -d ktcc -f 914595
                                      oid2name -d ktcc -f 532196
                                      oid2name -d ktcc -f 532192
                                      oid2name -d ktcc -f 532189
                                      oid2name -d ktcc -f 532197
                                      oid2name -d ktcc -f 532205
                                      oid2name -d ktcc -f 597054
                                      oid2name -d ktcc -f 532193
                                      oid2name -d ktcc -f 547740
                                      oid2name -d ktcc -f 592627
                                      914595 cln_useroperatedlog


                                      这里有个问题就是这些表的总共操作也没多少,理论上不应当产生如此高的WAL的日志量;

                                      这里有几个方向:

                                      1 怀疑age不够了

                                        SELECT CAST(txid_current() AS text)
                                        txid_current
                                        --------------
                                        155524684
                                        (1 row)
                                        select datname,age(datfrozenxid),2^31-age(datfrozenxid) age_remain from pg_database order by age(datfrozenxid) desc

                                        均很小;远没到达2的31次方;

                                        2 再次做wal日志解析

                                        用内置了wal日志的解析插件工具pg_recvlogical再次分析(未完待续)


                                        「喜欢文章,快来给作者赞赏墨值吧」
                                        文章转载自pg那些事,如果涉嫌侵权,请发送邮件至:contact@modb.pro进行举报,并提供相关证据,一经查实,墨天轮将立刻删除相关内容。

                                        评论

                                        关注
                                        最新发布
                                        暂无内容,敬请期待...
                                        数据库资讯
                                        最新 热门 更多
                                        本月热门
                                        近期活动
                                        全部
                                        暂无活动,敬请期待...
                                        相关课程
                                        全部
                                        暂无课程,敬请期待...