Re: pg14b1 stuck in lazy_scan_prune/heap_page_prune of pg_statistic

On Sun, Jun 06, 2021 at 07:26:22PM +0200, Matthias van de Meent wrote:
> I think it would be helpful for further debugging if we would have the
> state of the all tuples on that page (well, the tuple headers with
> their transactionids and their line pointers), as that would help with
> determining if my suspicion could be correct.

This is the state of the page after I killed the cluster and started a
postmaster on a copy of its datadir, with autovacuum=off:

SELECT lp, lp_off, lp_flags, lp_len, t_xmin, t_xmax, t_field3, t_ctid, t_infomask2, t_infomask, t_hoff, t_bits, t_oid
FROMheap_page_items(get_raw_page('pg_statistic', 75)) ;
 
 lp | lp_off | lp_flags | lp_len |  t_xmin   |  t_xmax   | t_field3 | t_ctid  | t_infomask2 | t_infomask | t_hoff |
        t_bits              | t_oid 
 

----+--------+----------+--------+-----------+-----------+----------+---------+-------------+------------+--------+----------------------------------+-------
  1 |      0 |        3 |      0 |           |           |          |         |             |            |        |
                            |      
 
  2 |      0 |        3 |      0 |           |           |          |         |             |            |        |
                            |      
 
  3 |      0 |        3 |      0 |           |           |          |         |             |            |        |
                            |      
 
  4 |   7624 |        1 |    564 | 913726913 | 913730328 |        0 | (83,19) |          31 |       8451 |     32 |
11111111111111111111101000100000|      
 
  5 |   6432 |        1 |   1188 | 913726913 | 913730328 |        0 | (83,20) |          31 |       8451 |     32 |
11111111111111111111110100110000|      
 
  6 |   6232 |        1 |    195 | 913726913 | 913730328 |        0 | (83,21) |          31 |       8451 |     32 |
11111111111111111111111000100000|      
 
  7 |   6032 |        1 |    195 | 913726913 | 913730328 |        0 | (83,22) |          31 |       8451 |     32 |
11111111111111111111111000100000|      
 
  8 |   5848 |        1 |    181 | 913726913 | 913730328 |        0 | (83,23) |          31 |       8451 |     32 |
11111111111111111111111000100000|      
 
  9 |   5664 |        1 |    181 | 913726913 | 913730328 |        0 | (81,13) |          31 |       8451 |     32 |
11111111111111111111111000100000|      
 
 10 |   5488 |        1 |    176 | 913726913 | 913730328 |        0 | (81,14) |          31 |       8451 |     32 |
11111111111111111111111000100000|      
 
 11 |   5312 |        1 |    176 | 913726913 | 913730328 |        0 | (82,13) |          31 |       8451 |     32 |
11111111111111111111111000100000|      
 
 12 |   5128 |        1 |    181 | 913726913 | 913730328 |        0 | (79,57) |          31 |       8451 |     32 |
11111111111111111111111000100000|      
 
 13 |   4952 |        1 |    176 | 913726913 | 913730328 |        0 | (80,25) |          31 |       8451 |     32 |
11111111111111111111111000100000|      
 
 14 |   4776 |        1 |    176 | 913726913 | 913730328 |        0 | (80,26) |          31 |       8451 |     32 |
11111111111111111111111000100000|      
 
 15 |   4600 |        1 |    176 | 913726913 | 913730328 |        0 | (84,1)  |          31 |       8451 |     32 |
11111111111111111111111000100000|      
 
 16 |   4424 |        1 |    176 | 913726913 | 913730328 |        0 | (84,2)  |          31 |       8451 |     32 |
11111111111111111111111000100000|      
 
 17 |   4248 |        1 |    176 | 913726913 | 913730328 |        0 | (84,3)  |          31 |       8451 |     32 |
11111111111111111111111000100000|      
 
 18 |   2880 |        1 |   1364 | 913726913 | 913730328 |        0 | (84,4)  |          31 |       8451 |     32 |
11111111111111111111110100110000|      
 
 19 |   2696 |        1 |    179 | 913726914 |         0 |        0 | (75,19) |          31 |      10499 |     32 |
11111111111111111111111000100000|      
 
 20 |   2520 |        1 |    176 | 913726914 |         0 |        0 | (75,20) |          31 |      10499 |     32 |
11111111111111111111111000100000|      
 
 21 |   2336 |        1 |    179 | 913726914 |         0 |        0 | (75,21) |          31 |      10499 |     32 |
11111111111111111111111000100000|      
 
(21 rows)

(In the interest of full disclosure, this was a dumb cp -a of the live datadir
where the processes had been stuck for a day, and where I was unable to open a
client session).

8451 = HEAP_KEYS_UPDATED + 259 atts?

Note that after I vacuum pg_statistic, it looks like this:

ts=# SELECT lp, lp_off, lp_flags, lp_len, t_xmin, t_xmax, t_field3, t_ctid, t_infomask2, t_infomask, t_hoff, t_bits,
t_oidFROM heap_page_items(get_raw_page('pg_statistic', 75));
 
 lp | lp_off | lp_flags | lp_len |  t_xmin   | t_xmax | t_field3 | t_ctid  | t_infomask2 | t_infomask | t_hoff |
     t_bits              | t_oid 
 

----+--------+----------+--------+-----------+--------+----------+---------+-------------+------------+--------+----------------------------------+-------
  1 |      0 |        0 |      0 |           |        |          |         |             |            |        |
                         |
 
...
 18 |      0 |        0 |      0 |           |        |          |         |             |            |        |
                         |
 
 19 |   8008 |        1 |    179 | 913726914 |      0 |        0 | (75,19) |          31 |      10499 |     32 |
11111111111111111111111000100000|      
 
 20 |   7832 |        1 |    176 | 913726914 |      0 |        0 | (75,20) |          31 |      10499 |     32 |
11111111111111111111111000100000|      
 
 21 |   7648 |        1 |    179 | 913726914 |      0 |        0 | (75,21) |          31 |      10499 |     32 |
11111111111111111111111000100000|      
 

ts=# VACUUM VERBOSE pg_statistic;
|INFO:  vacuuming "pg_catalog.pg_statistic"
|INFO:  scanned index "pg_statistic_relid_att_inh_index" to remove 278403 row versions
|DETAIL:  CPU: user: 0.10 s, system: 0.00 s, elapsed: 0.14 s
|INFO:  "pg_statistic": removed 278403 dead item identifiers in 4747 pages
|DETAIL:  CPU: user: 0.12 s, system: 0.07 s, elapsed: 1.99 s
|INFO:  index "pg_statistic_relid_att_inh_index" now contains 1101 row versions in 758 pages
|DETAIL:  277271 index row versions were removed.
|747 index pages were newly deleted.
|747 index pages are currently deleted, of which 0 are currently reusable.
|CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s.
|INFO:  "pg_statistic": found 277216 removable, 1101 nonremovable row versions in 4758 out of 4758 pages
|DETAIL:  0 dead row versions cannot be removed yet, oldest xmin: 920282115
|0 pages removed.
|Skipped 0 pages due to buffer pins, 0 frozen pages.
|CPU: user: 1.75 s, system: 0.18 s, elapsed: 6.52 s.
|INFO:  "pg_statistic": truncated 4758 to 96 pages
|DETAIL:  CPU: user: 0.02 s, system: 0.02 s, elapsed: 0.06 s
|INFO:  vacuuming "pg_toast.pg_toast_2619"
|INFO:  scanned index "pg_toast_2619_index" to remove 30 row versions
|DETAIL:  CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
|INFO:  "pg_toast_2619": removed 30 dead item identifiers in 11 pages
|DETAIL:  CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
|INFO:  index "pg_toast_2619_index" now contains 115 row versions in 2 pages
|DETAIL:  3 index row versions were removed.
|0 index pages were newly deleted.
|0 index pages are currently deleted, of which 0 are currently reusable.
|CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s.
|INFO:  "pg_toast_2619": found 29 removable, 115 nonremovable row versions in 43 out of 43 pages
|DETAIL:  0 dead row versions cannot be removed yet, oldest xmin: 920282115
|0 pages removed.
|Skipped 0 pages due to buffer pins, 0 frozen pages.
|CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.03 s.
|VACUUM

Before:
 pg_catalog | pg_statistic | table | postgres | permanent   | heap          | 38 MB | 
After:
 pg_catalog | pg_statistic | table | postgres | permanent   | heap          | 1192 kB | 

I also have nearly-intact bt f from the partial core:

#0  0x00000000004fa063 in heap_prune_chain (prstate=0x7ffe7a0cd0c0, rootoffnum=4, buffer=14138) at pruneheap.c:592
        lp = <optimized out>
        tupdead = <optimized out>
        recent_dead = <optimized out>
        rootlp = 0x2aaab2089e24
        nchain = 0
        tup = {t_len = 564, t_self = {ip_blkid = {bi_hi = 0, bi_lo = 75}, ip_posid = 4}, t_tableOid = 2619, t_data =
0x2aaab208bbc8}
        ndeleted = 0
        priorXmax = 0
        htup = <optimized out>
        maxoff = 21
        offnum = 4
...
#1  heap_page_prune (relation=relation@entry=0x7f0349466d28, buffer=buffer@entry=14138, vistest=vistest@entry=0xe7bcc0
<GlobalVisCatalogRels>,old_snap_xmin=old_snap_xmin@entry=0, old_snap_ts=old_snap_ts@entry=0,
 
    report_stats=report_stats@entry=false, off_loc=<optimized out>, off_loc@entry=0x1d1b3fc) at pruneheap.c:278
        itemid = 0x2aaab2089e24
        ndeleted = 0
        page = 0x2aaab2089e00 <Address 0x2aaab2089e00 out of bounds>
        offnum = 4
        maxoff = 21
...
#2  0x00000000004fd9bf in lazy_scan_prune (vacrel=vacrel@entry=0x1d1b390, buf=buf@entry=14138, blkno=blkno@entry=75,
page=page@entry=0x2aaab2089e00<Address 0x2aaab2089e00 out of bounds>,
 
    vistest=vistest@entry=0xe7bcc0 <GlobalVisCatalogRels>, prunestate=prunestate@entry=0x7ffe7a0ced80) at
vacuumlazy.c:1712
        rel = 0x7f0349466d28
        offnum = 4
        maxoff = 21
        itemid = 0x2aaab2089e24
        tuple = {t_len = 564, t_self = {ip_blkid = {bi_hi = 0, bi_lo = 75}, ip_posid = 4}, t_tableOid = 2619, t_data =
0x2aaab208bbc8}
        res = <optimized out>
        tuples_deleted = 0
        lpdead_items = 0
        new_dead_tuples = 0
        num_tuples = 0
        live_tuples = 0
        nfrozen = 0

-- 
Justin