pg14b1 stuck in lazy_scan_prune/heap_page_prune of pg_statistic

On Sun, 6 Jun 2021 at 18:35, Justin Pryzby <pryzby@telsasoft.com> wrote:

An internal instance was rejecting connections with "too many clients".
I found a bunch of processes waiting on a futex and I was going to upgrade the
kernel (3.10.0-514) and dismiss the issue.

However, I also found an autovacuum chewing 100% CPU, and it appears the
problem is actually because autovacuum has locked a page of pg-statistic, and
every other process then gets stuck waiting in the planner. I checked a few
and found these:

My suspicion is that for some tuple on that page
HeapTupleSatisfiesVacuum() returns HEAPTUPLE_DEAD for a tuple that it
thinks should have been cleaned up by heap_page_prune, but isn't. This
would result in an infinite loop in lazy_scan_prune where the
condition on vacuumlazy.c:1800 will always be true, but the retry will
not do the job it's expected to do.

Apart from reporting this suspicion, I sadly can't help you much
further, as my knowledge and experience on vacuum and snapshot
horizons is only limited and probably won't help you in this.

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.

With regards,

Matthias van de Meent

Matthias van de Meent <boekewurm+postgres@gmail.com> writes:

On Sun, 6 Jun 2021 at 18:35, Justin Pryzby <pryzby@telsasoft.com> wrote:

However, I also found an autovacuum chewing 100% CPU, and it appears the
problem is actually because autovacuum has locked a page of pg-statistic, and
every other process then gets stuck waiting in the planner. I checked a few
and found these:

My suspicion is that for some tuple on that page
HeapTupleSatisfiesVacuum() returns HEAPTUPLE_DEAD for a tuple that it
thinks should have been cleaned up by heap_page_prune, but isn't. This
would result in an infinite loop in lazy_scan_prune where the
condition on vacuumlazy.c:1800 will always be true, but the retry will
not do the job it's expected to do.

Since Justin's got a debugger on the process already, it probably
wouldn't be too hard to confirm or disprove that theory by stepping
through the code.

regards, tom lane

On Sun, Jun 6, 2021 at 9:35 AM Justin Pryzby <pryzby@telsasoft.com> wrote:

I'll leave the instance running for a little bit before restarting (or kill-9)
in case someone requests more info.

How about dumping the page image out, and sharing it with the list?
This procedure should work fine from gdb:

https://wiki.postgresql.org/wiki/Getting_a_stack_trace_of_a_running_PostgreSQL_backend_on_Linux/BSD#Dumping_a_page_image_from_within_GDB

I suggest that you dump the "page" pointer inside lazy_scan_prune(). I
imagine that you have the instance already stuck in an infinite loop,
so what we'll probably see from the page image is the page after the
first prune and another no-progress prune.

--
Peter Geoghegan

Hi,

On Sun, Jun 6, 2021, at 10:59, Tom Lane wrote:

Matthias van de Meent <boekewurm+postgres@gmail.com> writes:

On Sun, 6 Jun 2021 at 18:35, Justin Pryzby <pryzby@telsasoft.com> wrote:

However, I also found an autovacuum chewing 100% CPU, and it appears the
problem is actually because autovacuum has locked a page of pg-statistic, and
every other process then gets stuck waiting in the planner. I checked a few
and found these:

My suspicion is that for some tuple on that page
HeapTupleSatisfiesVacuum() returns HEAPTUPLE_DEAD for a tuple that it
thinks should have been cleaned up by heap_page_prune, but isn't. This
would result in an infinite loop in lazy_scan_prune where the
condition on vacuumlazy.c:1800 will always be true, but the retry will
not do the job it's expected to do.

Since Justin's got a debugger on the process already, it probably
wouldn't be too hard to confirm or disprove that theory by stepping
through the code.

If that turns out to be the issue, it'd be good to check what prevents the tuple from being considered fully dead, by stepping through the visibility test...

Andres

On Sun, Jun 06, 2021 at 11:00:38AM -0700, Peter Geoghegan wrote:

On Sun, Jun 6, 2021 at 9:35 AM Justin Pryzby <pryzby@telsasoft.com> wrote:

I'll leave the instance running for a little bit before restarting (or kill-9)
in case someone requests more info.

How about dumping the page image out, and sharing it with the list?
This procedure should work fine from gdb:

Sorry, but I already killed the process to try to follow Matthias' suggestion.
I have a core file from "gcore" but it looks like it's incomplete and the
address is now "out of bounds"...

#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>,

I saved a copy of the datadir, but a manual "vacuum" doesn't trigger the
problem. So if Matthias' theory is right, it seems like there may be a race
condition. Maybe that goes without saying.

--
Justin

On Sun, Jun 6, 2021 at 11:43 AM Justin Pryzby <pryzby@telsasoft.com> wrote:

Sorry, but I already killed the process to try to follow Matthias' suggestion.
I have a core file from "gcore" but it looks like it's incomplete and the
address is now "out of bounds"...

Based on what you said about ending up back in lazy_scan_prune()
alone, I think he's right. That is, I agree that it's very likely that
the stuck VACUUM would not have become stuck had the "goto retry on
HEAPTUPLE_DEAD inside lazy_scan_prune" thing not been added by commit
8523492d4e3. But that in itself doesn't necessarily implicate commit
8523492d4e3.

The interesting question is: Why doesn't heap_page_prune() ever agree
with HeapTupleSatisfiesVacuum() calls made from lazy_scan_prune(), no
matter how many times the call to heap_page_prune() is repeated? (It's
repeated to try to resolve the disagreement that aborted xacts can
sometimes cause.)

If I had to guess I'd say that the underlying problem has something to
do with heap_prune_satisfies_vacuum() not agreeing with
HeapTupleSatisfiesVacuum(), perhaps only when GlobalVisCatalogRels is
used. But that's a pretty wild guess at this point.

--
Peter Geoghegan

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 FROM 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 | 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_oid FROM 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

On Sun, Jun 06, 2021 at 11:00:38AM -0700, Peter Geoghegan wrote:

On Sun, Jun 6, 2021 at 9:35 AM Justin Pryzby <pryzby@telsasoft.com> wrote:

I'll leave the instance running for a little bit before restarting (or kill-9)
in case someone requests more info.

How about dumping the page image out, and sharing it with the list?
This procedure should work fine from gdb:

https://wiki.postgresql.org/wiki/Getting_a_stack_trace_of_a_running_PostgreSQL_backend_on_Linux/BSD#Dumping_a_page_image_from_within_GDB

I suggest that you dump the "page" pointer inside lazy_scan_prune(). I
imagine that you have the instance already stuck in an infinite loop,
so what we'll probably see from the page image is the page after the
first prune and another no-progress prune.

The cluster was again rejecting with "too many clients already".

I was able to open a shell this time, but it immediately froze when I tried to
tab complete "pg_stat_acti"...

I was able to dump the page image, though - attached. I can send you its
"data" privately, if desirable. I'll also try to step through this.

postgres=# 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 FROM heap_page_items(pg_read_binary_file('/tmp/dump_block.page'));
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 | 1320 | 1 | 259 | 926025112 | 0 | 0 | (1,1) | 32799 | 10499 | 32 | 11111111111111111111111000100000 |
2 | 8088 | 1 | 104 | 926018702 | 0 | 0 | (1,2) | 32799 | 10497 | 32 | 11111111111111111111100000000000 |
3 | 0 | 0 | 0 | | | | | | | | |
4 | 7904 | 1 | 179 | 926018702 | 0 | 0 | (1,4) | 32799 | 10499 | 32 | 11111111111111111111111000100000 |
5 | 7728 | 1 | 176 | 926018702 | 0 | 0 | (1,5) | 32799 | 10499 | 32 | 11111111111111111111111000100000 |
6 | 7464 | 1 | 259 | 926014884 | 926025112 | 0 | (1,1) | 49183 | 9475 | 32 | 11111111111111111111111000100000 |
7 | 2 | 2 | 0 | | | | | | | | |
8 | 4 | 2 | 0 | | | | | | | | |
9 | 19 | 2 | 0 | | | | | | | | |
10 | 0 | 0 | 0 | | | | | | | | |
11 | 20 | 2 | 0 | | | | | | | | |
12 | 5792 | 1 | 1666 | 926014887 | 0 | 0 | (1,12) | 31 | 10499 | 32 | 11111111111111111111101000100000 |
13 | 5 | 2 | 0 | | | | | | | | |
14 | 3912 | 1 | 1880 | 925994211 | 0 | 0 | (1,14) | 31 | 10499 | 32 | 11111111111111111111110100110000 |
15 | 0 | 3 | 0 | | | | | | | | |
16 | 18 | 2 | 0 | | | | | | | | |
17 | 0 | 3 | 0 | | | | | | | | |
18 | 1936 | 1 | 1976 | 926013259 | 0 | 0 | (1,18) | 32799 | 10499 | 32 | 11111111111111111111110100110000 |
19 | 1760 | 1 | 176 | 926014887 | 0 | 0 | (1,19) | 32799 | 10499 | 32 | 11111111111111111111111000100000 |
20 | 1584 | 1 | 176 | 926014889 | 0 | 0 | (1,20) | 32799 | 10499 | 32 | 11111111111111111111111000100000 |
21 | 6 | 2 | 0 | | | | | | | | |
22 | 0 | 3 | 0 | | | | | | | | |
23 | 0 | 3 | 0 | | | | | | | | |
24 | 0 | 3 | 0 | | | | | | | | |
25 | 0 | 3 | 0 | | | | | | | | |
26 | 0 | 3 | 0 | | | | | | | | |
27 | 0 | 3 | 0 | | | | | | | | |
28 | 0 | 3 | 0 | | | | | | | | |
(28 rows)

No great surprise that it's again in pg_statistic.

#0 GetPrivateRefCountEntry (buffer=buffer@entry=411, do_move=do_move@entry=false) at bufmgr.c:313
#1 0x00000000007ecb4f in GetPrivateRefCount (buffer=411) at bufmgr.c:398
#2 BufferGetBlockNumber (buffer=buffer@entry=411) at bufmgr.c:2762
#3 0x00000000004fa0f3 in heap_prune_chain (prstate=0x7fff7e4a9180, rootoffnum=7, buffer=411) at pruneheap.c:625
#4 heap_page_prune (relation=relation@entry=0x7fe636faed28, buffer=buffer@entry=411, 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=0x12b433c) at pruneheap.c:278
#5 0x00000000004fd9bf in lazy_scan_prune (vacrel=vacrel@entry=0x12b42d0, buf=buf@entry=411, blkno=blkno@entry=1, page=page@entry=0x2aaaab54be00 "J\f", vistest=vistest@entry=0xe7bcc0 <GlobalVisCatalogRels>,
prunestate=prunestate@entry=0x7fff7e4aae40) at vacuumlazy.c:1712
#6 0x0000000000500263 in lazy_scan_heap (aggressive=<optimized out>, params=0x12ce89c, vacrel=<optimized out>) at vacuumlazy.c:1347
#7 heap_vacuum_rel (rel=0x7fe636faed28, params=0x12ce89c, bstrategy=<optimized out>) at vacuumlazy.c:612
#8 0x000000000067418a in table_relation_vacuum (bstrategy=<optimized out>, params=0x12ce89c, rel=0x7fe636faed28) at ../../../src/include/access/tableam.h:1678
#9 vacuum_rel (relid=2619, relation=<optimized out>, params=params@entry=0x12ce89c) at vacuum.c:2001

--
Justin

On Sun, Jun 06, 2021 at 01:59:10PM -0400, Tom Lane wrote:

Matthias van de Meent <boekewurm+postgres@gmail.com> writes:

On Sun, 6 Jun 2021 at 18:35, Justin Pryzby <pryzby@telsasoft.com> wrote:

However, I also found an autovacuum chewing 100% CPU, and it appears the
problem is actually because autovacuum has locked a page of pg-statistic, and
every other process then gets stuck waiting in the planner. I checked a few
and found these:

My suspicion is that for some tuple on that page
HeapTupleSatisfiesVacuum() returns HEAPTUPLE_DEAD for a tuple that it
thinks should have been cleaned up by heap_page_prune, but isn't. This
would result in an infinite loop in lazy_scan_prune where the
condition on vacuumlazy.c:1800 will always be true, but the retry will
not do the job it's expected to do.

Since Justin's got a debugger on the process already, it probably
wouldn't be too hard to confirm or disprove that theory by stepping
through the code.

Breakpoint 2, HeapTupleSatisfiesVacuum (htup=htup@entry=0x7fff7e4a9ca0, OldestXmin=926025113, buffer=buffer@entry=411) at heapam_visibility.c:1163
1163 heapam_visibility.c: No such file or directory.
(gdb) fin
Run till exit from #0 HeapTupleSatisfiesVacuum (htup=htup@entry=0x7fff7e4a9ca0, OldestXmin=926025113, buffer=buffer@entry=411) at heapam_visibility.c:1163
lazy_scan_prune (vacrel=vacrel@entry=0x12b42d0, buf=buf@entry=411, blkno=blkno@entry=1, page=page@entry=0x2aaaab54be00 "J\f", vistest=vistest@entry=0xe7bcc0 <GlobalVisCatalogRels>, prunestate=prunestate@entry=0x7fff7e4aae40)
at vacuumlazy.c:1790
1790 vacuumlazy.c: No such file or directory.
Value returned is $23 = HEAPTUPLE_DEAD

offnum = 6
tuple = {t_len = 259, t_self = {ip_blkid = {bi_hi = 0, bi_lo = 1}, ip_posid = 6}, t_tableOid = 2619, t_data = 0x2aaaab54db28}
res = HEAPTUPLE_DEAD

(gdb) p *itemid
$51 = {lp_off = 7464, lp_flags = 1, lp_len = 259}

(gdb) p *tuple->t_data
$54 = {t_choice = {t_heap = {t_xmin = 926014884, t_xmax = 926025112, t_field3 = {t_cid = 0, t_xvac = 0}}, t_datum = {datum_len_ = 926014884, datum_typmod = 926025112, datum_typeid = 0}}, t_ctid = {ip_blkid = {bi_hi = 0,
bi_lo = 1}, ip_posid = 1}, t_infomask2 = 49183, t_infomask = 9475, t_hoff = 32 ' ', t_bits = 0x2aaaab54db3f "\377\377\177\004"}

lp_flags = LP_NORMAL 1 ??
t_infomask2 = HEAP_ONLY_TUPLE | HEAP_HOT_UPDATED + 31 atts
infomask = HEAP_UPDATED | HEAP_XMAX_COMMITTED | HEAP_XMIN_COMMITTED | HEAP_HASVARWIDTH | HEAP_HASNULL

--
Justin

On Tue, 8 Jun 2021 at 13:03, Justin Pryzby <pryzby@telsasoft.com> wrote:

On Sun, Jun 06, 2021 at 11:00:38AM -0700, Peter Geoghegan wrote:

On Sun, Jun 6, 2021 at 9:35 AM Justin Pryzby <pryzby@telsasoft.com> wrote:

I'll leave the instance running for a little bit before restarting (or kill-9)
in case someone requests more info.

How about dumping the page image out, and sharing it with the list?
This procedure should work fine from gdb:

https://wiki.postgresql.org/wiki/Getting_a_stack_trace_of_a_running_PostgreSQL_backend_on_Linux/BSD#Dumping_a_page_image_from_within_GDB

I suggest that you dump the "page" pointer inside lazy_scan_prune(). I
imagine that you have the instance already stuck in an infinite loop,
so what we'll probably see from the page image is the page after the
first prune and another no-progress prune.

The cluster was again rejecting with "too many clients already".

I was able to open a shell this time, but it immediately froze when I tried to
tab complete "pg_stat_acti"...

I was able to dump the page image, though - attached. I can send you its
"data" privately, if desirable. I'll also try to step through this.

Could you attach a dump of lazy_scan_prune's vacrel, all the global
visibility states (GlobalVisCatalogRels, and possibly
GlobalVisSharedRels, GlobalVisDataRels, and GlobalVisTempRels), and
heap_page_prune's PruneState?

Additionally, the locals of lazy_scan_prune (more specifically, the
'offnum' when it enters heap_page_prune) would also be appreciated, as
it helps indicate the tuple.

I've been looking at whatever might have done this, and I'm currently
stuck on lacking information in GlobalVisCatalogRels and the
PruneState.

One curiosity that I did notice is that the t_xmax of the problematic
tuples has been exactly one lower than the OldestXmin. Not weird, but
a curiosity.

With regards,

Matthias van de Meent.

PS. Attached a few of my current research notes, which are mainly
comparisons between heap_prune_satisfies_vacuum and
HeapTupleSatisfiesVacuum.

On Tue, Jun 08, 2021 at 01:54:41PM +0200, Matthias van de Meent wrote:

On Tue, 8 Jun 2021 at 13:03, Justin Pryzby <pryzby@telsasoft.com> wrote:

On Sun, Jun 06, 2021 at 11:00:38AM -0700, Peter Geoghegan wrote:

On Sun, Jun 6, 2021 at 9:35 AM Justin Pryzby <pryzby@telsasoft.com> wrote:

I'll leave the instance running for a little bit before restarting (or kill-9)
in case someone requests more info.

How about dumping the page image out, and sharing it with the list?
This procedure should work fine from gdb:

https://wiki.postgresql.org/wiki/Getting_a_stack_trace_of_a_running_PostgreSQL_backend_on_Linux/BSD#Dumping_a_page_image_from_within_GDB

I suggest that you dump the "page" pointer inside lazy_scan_prune(). I
imagine that you have the instance already stuck in an infinite loop,
so what we'll probably see from the page image is the page after the
first prune and another no-progress prune.

The cluster was again rejecting with "too many clients already".

I was able to open a shell this time, but it immediately froze when I tried to
tab complete "pg_stat_acti"...

I was able to dump the page image, though - attached. I can send you its
"data" privately, if desirable. I'll also try to step through this.

Could you attach a dump of lazy_scan_prune's vacrel, all the global
visibility states (GlobalVisCatalogRels, and possibly
GlobalVisSharedRels, GlobalVisDataRels, and GlobalVisTempRels), and
heap_page_prune's PruneState?

(gdb) p *vacrel
$56 = {rel = 0x7fe636faed28, indrels = 0x12b4440, nindexes = 1, do_index_vacuuming = true, do_index_cleanup = true, do_failsafe = false, bstrategy = 0x1210340, lps = 0x0, old_rel_pages = 81, old_live_tuples = 1100, relfrozenxid = 921613998, relminmxid = 53878631, OldestXmin = 926025113, FreezeLimit = 876025113, MultiXactCutoff = 49085856, relnamespace = 0x12b4460 "pg_catalog", relname = 0x12b4488 "pg_statistic", indname = 0x0, blkno = 1, offnum = 6, phase = VACUUM_ERRCB_PHASE_SCAN_HEAP, dead_tuples = 0x127a980, rel_pages = 81, scanned_pages = 2, pinskipped_pages = 0, frozenskipped_pages = 0, tupcount_pages = 2, pages_removed = 0, lpdead_item_pages = 1, nonempty_pages = 1, lock_waiter_detected = false, new_rel_tuples = 0, new_live_tuples = 0, indstats = 0x12b4568, num_index_scans = 0, tuples_deleted = 0, lpdead_items = 3, new_dead_tuples = 0, num_tuples = 14, live_tuples = 14}

(gdb) p GlobalVisCatalogRels
$57 = {definitely_needed = {value = 926025113}, maybe_needed = {value = 926025112}}
(gdb) p GlobalVisSharedRels
$58 = {definitely_needed = {value = 926025113}, maybe_needed = {value = 926025112}}
(gdb) p GlobalVisDataRels
$59 = {definitely_needed = {value = 926025113}, maybe_needed = {value = 926025113}}
(gdb) p GlobalVisTempRels
$60 = {definitely_needed = {value = 926025113}, maybe_needed = {value = 926025113}}

I don't know when you want prstate from, but here it is at some point:

(gdb) p *prstate
$77 = {rel = 0x7fe636faed28, vistest = 0xe7bcc0 <GlobalVisCatalogRels>, old_snap_ts = 0, old_snap_xmin = 0, old_snap_used = false, new_prune_xid = 0, latestRemovedXid = 0, nredirected = 0, ndead = 0, nunused = 0,

Additionally, the locals of lazy_scan_prune (more specifically, the
'offnum' when it enters heap_page_prune) would also be appreciated, as
it helps indicate the tuple.

Breakpoint 1, heap_page_prune (relation=relation@entry=0x7fe636faed28, buffer=buffer@entry=411, 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=off_loc@entry=0x12b433c) at pruneheap.c:225
225 pruneheap.c: No such file or directory.
(gdb) up
#1 0x00000000004fd9bf in lazy_scan_prune (vacrel=vacrel@entry=0x12b42d0, buf=buf@entry=411, blkno=blkno@entry=1, page=page@entry=0x2aaaab54be00 "J\f", vistest=vistest@entry=0xe7bcc0 <GlobalVisCatalogRels>,
prunestate=prunestate@entry=0x7fff7e4aae40) at vacuumlazy.c:1712
1712 vacuumlazy.c: No such file or directory.
(gdb) info locals
rel = 0x7fe636faed28
offnum = 6
maxoff = 28
itemid = 0x2aaaab54be2c
tuple = {t_len = 259, t_self = {ip_blkid = {bi_hi = 0, bi_lo = 1}, ip_posid = 6}, t_tableOid = 2619, t_data = 0x2aaaab54db28}
res = <optimized out>
tuples_deleted = 0
lpdead_items = 0
new_dead_tuples = 0
num_tuples = 0
live_tuples = 0
nfrozen = 0

Maybe you need to know that this is also returning RECENTLY_DEAD.

Breakpoint 4, heap_prune_satisfies_vacuum (prstate=prstate@entry=0x7fff7e4a9180, tup=tup@entry=0x7fff7e4a8f10, buffer=buffer@entry=411) at pruneheap.c:423
423 in pruneheap.c
(gdb)
Run till exit from #0 heap_prune_satisfies_vacuum (prstate=prstate@entry=0x7fff7e4a9180, tup=tup@entry=0x7fff7e4a8f10, buffer=buffer@entry=411) at pruneheap.c:423
0x00000000004fa887 in heap_prune_chain (prstate=0x7fff7e4a9180, rootoffnum=6, buffer=411) at pruneheap.c:560
560 in pruneheap.c
Value returned is $72 = HEAPTUPLE_RECENTLY_DEAD

tup = {t_len = 259, t_self = {ip_blkid = {bi_hi = 0, bi_lo = 1}, ip_posid = 6}, t_tableOid = 2619, t_data = 0x2aaaab54db28}
(gdb) p * htup
$82 = {t_choice = {t_heap = {t_xmin = 926014884, t_xmax = 926025112, t_field3 = {t_cid = 0, t_xvac = 0}}, t_datum = {datum_len_ = 926014884, datum_typmod = 926025112, datum_typeid = 0}}, t_ctid = {ip_blkid = {bi_hi = 0, bi_lo = 1}, ip_posid = 1}, t_infomask2 = 49183, t_infomask = 9475, t_hoff = 32 ' ', t_bits = 0x2aaaab54db3f "\377\377\177\004"}

--
Justin
System Administrator
Telsasoft
+1-952-707-8581

On Tue, 8 Jun 2021 at 14:11, Justin Pryzby <pryzby@telsasoft.com> wrote:

On Tue, Jun 08, 2021 at 01:54:41PM +0200, Matthias van de Meent wrote:

On Tue, 8 Jun 2021 at 13:03, Justin Pryzby <pryzby@telsasoft.com> wrote:

On Sun, Jun 06, 2021 at 11:00:38AM -0700, Peter Geoghegan wrote:

On Sun, Jun 6, 2021 at 9:35 AM Justin Pryzby <pryzby@telsasoft.com> wrote:

I'll leave the instance running for a little bit before restarting (or kill-9)
in case someone requests more info.

How about dumping the page image out, and sharing it with the list?
This procedure should work fine from gdb:

https://wiki.postgresql.org/wiki/Getting_a_stack_trace_of_a_running_PostgreSQL_backend_on_Linux/BSD#Dumping_a_page_image_from_within_GDB

I suggest that you dump the "page" pointer inside lazy_scan_prune(). I
imagine that you have the instance already stuck in an infinite loop,
so what we'll probably see from the page image is the page after the
first prune and another no-progress prune.

The cluster was again rejecting with "too many clients already".

I was able to open a shell this time, but it immediately froze when I tried to
tab complete "pg_stat_acti"...

I was able to dump the page image, though - attached. I can send you its
"data" privately, if desirable. I'll also try to step through this.

Could you attach a dump of lazy_scan_prune's vacrel, all the global
visibility states (GlobalVisCatalogRels, and possibly
GlobalVisSharedRels, GlobalVisDataRels, and GlobalVisTempRels), and
heap_page_prune's PruneState?

(gdb) p *vacrel
$56 = {... OldestXmin = 926025113, ...}

(gdb) p GlobalVisCatalogRels
$57 = {definitely_needed = {value = 926025113}, maybe_needed = {value = 926025112}}

This maybe_needed is older than the OldestXmin, which indeed gives us
this problematic behaviour:

heap_prune_satisfies_vacuum considers 1 more transaction to be
unvacuumable, and thus indeed won't vacuum that tuple that
HeapTupleSatisfiesVacuum does want to be vacuumed.

The new open question is now: Why is
GlobalVisCatalogRels->maybe_needed < OldestXmin? IIRC
GLobalVisCatalogRels->maybe_needed is constructed from the same
ComputeXidHorizonsResult->catalog_oldest_nonremovable which later is
returned to be used in vacrel->OldestXmin.

Maybe you need to know that this is also returning RECENTLY_DEAD.

I had expected that, but good to have confirmation.

Thanks for the information!

With regards,

Matthias van de Meent.

On Tue, Jun 08, 2021 at 02:27:14PM +0200, Matthias van de Meent wrote:

Thanks for the information!

I created an apparently-complete core file by first doing this:
| echo 127 |sudo tee /proc/22591/coredump_filter

*and updated wiki:Developer_FAQ to work with huge pages

I'm planning to kill the process shortly if nobody asks for anything else.

On 2021-Jun-06, Justin Pryzby wrote:

However, I also found an autovacuum chewing 100% CPU, and it appears the
problem is actually because autovacuum has locked a page of pg-statistic, and
every other process then gets stuck waiting in the planner. I checked a few
and found these:

[...]

Hmm ... I wonder if this could be related to commits d9d076222f5b,
c98763bf51bf, etc. I don't have any connecting thoughts other than the
tuple visibility code being involved. Do you see any procs with the
PROC_IN_SAFE_IC flag set?

--
�lvaro Herrera 39�49'30"S 73�17'W

Hi,

On 2021-06-08 14:27:14 +0200, Matthias van de Meent wrote:

heap_prune_satisfies_vacuum considers 1 more transaction to be
unvacuumable, and thus indeed won't vacuum that tuple that
HeapTupleSatisfiesVacuum does want to be vacuumed.

The new open question is now: Why is
GlobalVisCatalogRels->maybe_needed < OldestXmin? IIRC
GLobalVisCatalogRels->maybe_needed is constructed from the same
ComputeXidHorizonsResult->catalog_oldest_nonremovable which later is
returned to be used in vacrel->OldestXmin.

The horizon used by pruning is only updated once per transaction (well,
approximately). What presumably is happening is that the retry loop is
retrying, without updating the horizon, therefore the same thing is
happening over and over again?

Greetings,

Andres Freund

On Tue, Jun 08, 2021 at 12:06:02PM -0400, Alvaro Herrera wrote:

On 2021-Jun-06, Justin Pryzby wrote:

However, I also found an autovacuum chewing 100% CPU, and it appears the
problem is actually because autovacuum has locked a page of pg-statistic, and
every other process then gets stuck waiting in the planner. I checked a few
and found these:

Hmm ... I wonder if this could be related to commits d9d076222f5b,
c98763bf51bf, etc. I don't have any connecting thoughts other than the
tuple visibility code being involved. Do you see any procs with the
PROC_IN_SAFE_IC flag set?

Can you give me a hint how to do that from a corefile ?

I got this far:
(gdb) p MyProc->links
$13 = {prev = 0x0, next = 0x0}

I do have a reindex script which runs CIC, and it does looks suspicious.

<<Mon Jun 7 22:00:54 CDT 2021: starting db=ts
...
Mon Jun 7 22:01:16 CDT 2021: ts: pg_subscription_rel: pg_subscription_rel_srrelid_srsubid_index(reindex system)...
Mon Jun 7 22:01:16 CDT 2021: ts: pg_subscription: pg_subscription_oid_index(reindex system)...
Mon Jun 7 22:01:16 CDT 2021: ts: pg_subscription: pg_subscription_subname_index(reindex system)...
Mon Jun 7 22:01:16 CDT 2021: ts: pg_subscription: pg_toast.pg_toast_6100_index(reindex system)...
Mon Jun 7 22:01:17 CDT 2021: ts: pg_statistic_ext_data: pg_statistic_ext_data_stxoid_index(reindex system)...
Mon Jun 7 22:01:17 CDT 2021: ts: pg_statistic_ext_data: pg_toast.pg_toast_3429_index(reindex system)...
Mon Jun 7 22:01:17 CDT 2021: ts: pg_statistic_ext: pg_statistic_ext_name_index(reindex system)...
Mon Jun 7 22:01:17 CDT 2021: ts: pg_statistic_ext: pg_statistic_ext_oid_index(reindex system)...
Mon Jun 7 22:01:17 CDT 2021: ts: pg_statistic_ext: pg_statistic_ext_relid_index(reindex system)...
Mon Jun 7 22:01:17 CDT 2021: ts: pg_statistic_ext: pg_toast.pg_toast_3381_index(reindex system)...
Mon Jun 7 22:01:17 CDT 2021: ts: pg_statistic: pg_statistic_relid_att_inh_index(reindex system)...
Mon Jun 7 22:02:56 CDT 2021: ts: pg_statistic: pg_toast.pg_toast_2619_index(reindex system)...
Mon Jun 7 22:02:57 CDT 2021: ts: pg_statio_all_tables_snap: pg_statio_all_tables_snap_t_idx(reindex non-partitioned)...
ERROR: canceling statement due to statement timeout
reindex: warning, dropping invalid/unswapped index: pg_statio_all_tables_snap_t_idx_ccnew
Mon Jun 7 23:02:57 CDT 2021: ts: pg_statio_all_tables_snap: pg_toast.pg_toast_33011_index(reindex system)...
Mon Jun 7 23:02:57 CDT 2021: ts: pg_statio_all_indexes_snap: pg_statio_all_indexes_snap_t_idx(reindex non-partitioned)...
ERROR: canceling statement due to statement timeout
reindex: warning, dropping invalid/unswapped index: pg_statio_all_indexes_snap_t_idx_ccnew
Tue Jun 8 00:02:57 CDT 2021: ts: pg_statio_all_indexes_snap: pg_toast.pg_toast_33020_index(reindex system)...
Tue Jun 8 00:02:57 CDT 2021: ts: pg_shseclabel: pg_shseclabel_object_index(reindex system)...
Tue Jun 8 00:02:58 CDT 2021: ts: pg_shseclabel: pg_toast.pg_toast_3592_index(reindex system)...
Tue Jun 8 00:02:58 CDT 2021: ts: pg_shdescription: pg_shdescription_o_c_index(reindex system)...
Tue Jun 8 00:02:58 CDT 2021: ts: pg_shdescription: pg_toast.pg_toast_2396_index(reindex system)...
...
Tue Jun 8 00:02:57 CDT 2021: ts: pg_statio_all_indexes_snap: pg_toast.pg_toast_33020_index(reindex system)...
Tue Jun 8 00:02:57 CDT 2021: ts: pg_shseclabel: pg_shseclabel_object_index(reindex system)...
Tue Jun 8 00:02:58 CDT 2021: ts: pg_shseclabel: pg_toast.pg_toast_3592_index(reindex system)...
Tue Jun 8 00:02:58 CDT 2021: ts: pg_shdescription: pg_shdescription_o_c_index(reindex system)...
Tue Jun 8 00:02:58 CDT 2021: ts: pg_shdescription: pg_toast.pg_toast_2396_index(reindex system)...
...
Tue Jun 8 01:21:20 CDT 2021: ts: pg_aggregate: pg_aggregate_fnoid_index(reindex system)...
Tue Jun 8 01:21:20 CDT 2021: ts: pg_aggregate: pg_toast.pg_toast_2600_index(reindex system)...
Tue Jun 8 01:21:20 CDT 2021: ts: permissions: perm_group_idx(reindex non-partitioned)...
ERROR: canceling statement due to statement timeout
reindex: warning, dropping invalid/unswapped index: perm_group_idx_ccnew
Tue Jun 8 02:21:20 CDT 2021: ts: permissions: perm_user_idx(reindex non-partitioned)...
ERROR: canceling statement due to statement timeout
reindex: warning, dropping invalid/unswapped index: perm_user_idx_ccnew
Tue Jun 8 03:21:20 CDT 2021: ts: permissions: pg_toast.pg_toast_33577_index(reindex system)...
Tue Jun 8 03:21:20 CDT 2021: ts: patchfiles: patchfiles_filename_idx(reindex non-partitioned)...
ERROR: canceling statement due to statement timeout
reindex: warning, dropping invalid/unswapped index: patchfiles_filename_idx_ccnew
Tue Jun 8 04:21:21 CDT 2021: ts: patchfiles: patchfiles_pkey(reindex non-partitioned)...
ERROR: canceling statement due to statement timeout
reindex: warning, dropping invalid/unswapped index: patchfiles_pkey_ccnew

=> It's strange that these timed out, since the statio tables are less than
15MB, and permissions and patchfiles are both under 100kB.

And it seems to say that it time out after less than 1sec.

They're running this:
| PGOPTIONS="--deadlock_timeout=333ms -cstatement-timeout=3600s" psql -c "REINDEX INDEX CONCURRENTLY $i"
And if it times out, it then runs: $PSQL "DROP INDEX CONCURRENTLY $bad"

I've killed it a little bit ago, but I should've saved the start time of the
autovacuum. I found this:

#5 heap_vacuum_rel (rel=0x7fe636faed28, params=0x12ce89c, bstrategy=<optimized out>) at vacuumlazy.c:612
starttime = 676436464463888
ru0 = {tv = {tv_sec = 1623121264, tv_usec = 463887}, ru = {ru_utime = {tv_sec = 0, tv_usec = 77418}, ru_stime = {tv_sec = 0, tv_usec = 13866}, {ru_maxrss = 7440, __ru_maxrss_word = 7440}, {ru_ixrss = 0, __ru_ixrss_word = 0}, {
ru_idrss = 0, __ru_idrss_word = 0}, {ru_isrss = 0, __ru_isrss_word = 0}, {ru_minflt = 1826, __ru_minflt_word = 1826}, {ru_majflt = 1, __ru_majflt_word = 1}, {ru_nswap = 0, __ru_nswap_word = 0}, {ru_inblock = 2008,
__ru_inblock_word = 2008}, {ru_oublock = 192, __ru_oublock_word = 192}, {ru_msgsnd = 0, __ru_msgsnd_word = 0}, {ru_msgrcv = 0, __ru_msgrcv_word = 0}, {ru_nsignals = 0, __ru_nsignals_word = 0}, {ru_nvcsw = 29,
__ru_nvcsw_word = 29}, {ru_nivcsw = 9, __ru_nivcsw_word = 9}}}

$ date -d @1623121264
Mon Jun 7 22:01:04 CDT 2021

$ date -d '2000-01-01 UTC + 676436464seconds'
Mon Jun 7 22:01:04 CDT 2021

--
Justin

On 2021-Jun-08, Justin Pryzby wrote:

On Tue, Jun 08, 2021 at 12:06:02PM -0400, Alvaro Herrera wrote:

On 2021-Jun-06, Justin Pryzby wrote:

However, I also found an autovacuum chewing 100% CPU, and it appears the
problem is actually because autovacuum has locked a page of pg-statistic, and
every other process then gets stuck waiting in the planner. I checked a few
and found these:

Hmm ... I wonder if this could be related to commits d9d076222f5b,
c98763bf51bf, etc. I don't have any connecting thoughts other than the
tuple visibility code being involved. Do you see any procs with the
PROC_IN_SAFE_IC flag set?

Can you give me a hint how to do that from a corefile ?

(gdb) set $i=0
(gdb) set $total = ProcGlobal->allProcCount
(gdb) while($i<$total)

print ProcGlobal->allProcs[$i++]->statusFlags
end

--
�lvaro Herrera Valdivia, Chile
"In fact, the basic problem with Perl 5's subroutines is that they're not
crufty enough, so the cruft leaks out into user-defined code instead, by
the Conservation of Cruft Principle." (Larry Wall, Apocalypse 6)

Reminds me of the other bug that you also reported about a year ago,
Justin - which was never fixed. The one with the duplicate tids from a cic
(see pg 14 open item).

Is this essentially the same environment as the one that led to your other
bug report?

Peter Geoghegan
(Sent from my phone)

On Tue, Jun 08, 2021 at 02:01:51PM -0400, Alvaro Herrera wrote:

On 2021-Jun-08, Justin Pryzby wrote:

On Tue, Jun 08, 2021 at 12:06:02PM -0400, Alvaro Herrera wrote:

On 2021-Jun-06, Justin Pryzby wrote:

However, I also found an autovacuum chewing 100% CPU, and it appears the
problem is actually because autovacuum has locked a page of pg-statistic, and
every other process then gets stuck waiting in the planner. I checked a few
and found these:

Hmm ... I wonder if this could be related to commits d9d076222f5b,
c98763bf51bf, etc. I don't have any connecting thoughts other than the
tuple visibility code being involved. Do you see any procs with the
PROC_IN_SAFE_IC flag set?

Can you give me a hint how to do that from a corefile ?

(gdb) set $i=0
(gdb) set $total = ProcGlobal->allProcCount
(gdb) while($i<$total)

print ProcGlobal->allProcs[$i++]->statusFlags
end

They're all zero except for:

$201 = 1 '\001'
$202 = 3 '\003'
$203 = 1 '\001'

src/include/storage/proc.h-#define PROC_IS_AUTOVACUUM 0x01 /* is it an autovac worker? */
src/include/storage/proc.h-#define PROC_IN_VACUUM 0x02 /* currently running lazy vacuum */
src/include/storage/proc.h:#define PROC_IN_SAFE_IC 0x04 /* currently running CREATE INDEX

--
Justin