Re: PG12 autovac issues

All-

This started happening again.  DEBUG1 is enabled:

Mar 25 14:48:03 cowtn postgres[39720]: [35294-1] 2020-03-25
14:48:03.972 GMT [39720] DEBUG:  autovacuum: processing database
"template0"
Mar 25 14:48:06 cowtn postgres[39735]: [35294-1] 2020-03-25
14:48:06.545 GMT [39735] DEBUG:  autovacuum: processing database
"postgres"
Mar 25 14:48:11 cowtn postgres[39759]: [35294-1] 2020-03-25
14:48:11.284 GMT [39759] DEBUG:  autovacuum: processing database
"template1"
Mar 25 14:48:14 cowtn postgres[39772]: [35294-1] 2020-03-25
14:48:14.564 GMT [39772] DEBUG:  autovacuum: processing database
"feedi"
Mar 25 14:48:14 cowtn postgres[39772]: [35295-1] 2020-03-25
14:48:14.588 GMT [39772] LOG:  automatic vacuum of table
"feedi.pg_catalog.pg_statistic": index scans: 1
Mar 25 14:48:14 cowtn postgres[39772]: [35295-2] #011pages: 0 removed,
117 remain, 0 skipped due to pins, 0 skipped frozen
Mar 25 14:48:14 cowtn postgres[39772]: [35295-3] #011tuples: 477
removed, 704 remain, 0 are dead but not yet removable, oldest xmin:
189591147
Mar 25 14:48:14 cowtn postgres[39772]: [35295-4] #011buffer usage: 315
hits, 0 misses, 0 dirtied
Mar 25 14:48:14 cowtn postgres[39772]: [35295-5] #011avg read rate:
0.000 MB/s, avg write rate: 0.000 MB/s
Mar 25 14:48:14 cowtn postgres[39772]: [35295-6] #011system usage:
CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
Mar 25 14:48:15 cowtn postgres[39772]: [35296-1] 2020-03-25
14:48:15.606 GMT [39772] LOG:  automatic vacuum of table
"feedi.production.flightplans": index scans: 1
Mar 25 14:48:15 cowtn postgres[39772]: [35296-2] #011pages: 0 removed,
61331 remain, 0 skipped due to pins, 29772 skipped frozen
Mar 25 14:48:15 cowtn postgres[39772]: [35296-3] #011tuples: 21807
removed, 509983 remain, 1581 are dead but not yet removable, oldest
xmin: 189591147
Mar 25 14:48:15 cowtn postgres[39772]: [35296-4] #011buffer usage:
113684 hits, 0 misses, 1 dirtied
Mar 25 14:48:15 cowtn postgres[39772]: [35296-5] #011avg read rate:
0.000 MB/s, avg write rate: 0.008 MB/s
Mar 25 14:48:15 cowtn postgres[39772]: [35296-6] #011system usage:
CPU: user: 0.64 s, system: 0.12 s, elapsed: 1.00 s
Mar 25 14:48:16 cowtn postgres[39772]: [35297-1] 2020-03-25
14:48:16.537 GMT [39772] LOG:  automatic analyze of table
"feedi.production.flightplans" system usage: CPU: user: 0.83 s,
system: 0.03 s, elapsed: 0.93 s
Mar 25 14:48:16 cowtn postgres[39772]: [35298-1] 2020-03-25
14:48:16.627 GMT [39772] LOG:  automatic vacuum of table
"feedi.production.tita": index scans: 1
Mar 25 14:48:16 cowtn postgres[39772]: [35298-2] #011pages: 0 removed,
1711 remain, 0 skipped due to pins, 0 skipped frozen
Mar 25 14:48:16 cowtn postgres[39772]: [35298-3] #011tuples: 5936
removed, 75280 remain, 1079 are dead but not yet removable, oldest
xmin: 189591147
Mar 25 14:48:16 cowtn postgres[39772]: [35298-4] #011buffer usage:
5748 hits, 0 misses, 1 dirtied
Mar 25 14:48:16 cowtn postgres[39772]: [35298-5] #011avg read rate:
0.000 MB/s, avg write rate: 0.100 MB/s
Mar 25 14:48:16 cowtn postgres[39772]: [35298-6] #011system usage:
CPU: user: 0.06 s, system: 0.00 s, elapsed: 0.07 s
Mar 25 14:48:16 cowtn postgres[39772]: [35299-1] 2020-03-25
14:48:16.959 GMT [39772] LOG:  automatic analyze of table
"feedi.production.tita" system usage: CPU: user: 0.32 s, system: 0.00
s, elapsed: 0.33 s
Mar 25 14:48:16 cowtn postgres[39772]: [35300-1] 2020-03-25
14:48:16.969 GMT [39772] LOG:  automatic analyze of table
"feedi.production.virtual_clocks" system usage: CPU: user: 0.00 s,
system: 0.00 s, elapsed: 0.00 s
Mar 25 14:48:18 cowtn postgres[39790]: [35294-1] 2020-03-25
14:48:18.975 GMT [39790] DEBUG:  autovacuum: processing database
"template0"
Mar 25 14:48:21 cowtn postgres[39799]: [35294-1] 2020-03-25
14:48:21.546 GMT [39799] DEBUG:  autovacuum: processing database
"postgres"
Mar 25 14:48:22 cowtn postgres[39853]: [35294-1] 2020-03-25
14:48:22.446 GMT [39853] LOG:  connection received: host=10.4.4.11
port=25424
Mar 25 14:48:22 cowtn postgres[39853]: [35295-1] 2020-03-25
14:48:22.451 GMT [39853] LOG:  connection authorized: user=feedi
database=feedi SSL enabled (protocol=TLSv1.3,
cipher=TLS_AES_256_GCM_SHA384, bits=256, compression=off)
Mar 25 14:48:26 cowtn postgres[39875]: [35294-1] 2020-03-25
14:48:26.277 GMT [39875] DEBUG:  autovacuum: processing database
"postgres"
Mar 25 14:48:26 cowtn postgres[39875]: [35295-1] 2020-03-25
14:48:26.298 GMT [39875] DEBUG:  skipping redundant vacuum to prevent
wraparound of table "postgres.pg_catalog.pg_authid"
Mar 25 14:48:26 cowtn postgres[39875]: [35296-1] 2020-03-25
14:48:26.309 GMT [39875] DEBUG:  skipping redundant vacuum to prevent
wraparound of table "postgres.pg_catalog.pg_subscription"
Mar 25 14:48:26 cowtn postgres[39875]: [35297-1] 2020-03-25
14:48:26.319 GMT [39875] DEBUG:  skipping redundant vacuum to prevent
wraparound of table "postgres.pg_catalog.pg_database"
Mar 25 14:48:26 cowtn postgres[39875]: [35298-1] 2020-03-25
14:48:26.329 GMT [39875] DEBUG:  skipping redundant vacuum to prevent
wraparound of table "postgres.pg_catalog.pg_tablespace"
Mar 25 14:48:26 cowtn postgres[39875]: [35299-1] 2020-03-25
14:48:26.339 GMT [39875] DEBUG:  skipping redundant vacuum to prevent
wraparound of table "postgres.pg_catalog.pg_auth_members"
Mar 25 14:48:26 cowtn postgres[39875]: [35300-1] 2020-03-25
14:48:26.350 GMT [39875] DEBUG:  skipping redundant vacuum to prevent
wraparound of table "postgres.pg_catalog.pg_replication_origin"
Mar 25 14:48:26 cowtn postgres[39875]: [35301-1] 2020-03-25
14:48:26.360 GMT [39875] DEBUG:  skipping redundant vacuum to prevent
wraparound of table "postgres.pg_catalog.pg_shseclabel"
Mar 25 14:48:26 cowtn postgres[39875]: [35302-1] 2020-03-25
14:48:26.361 GMT [39875] DEBUG:  transaction ID wrap limit is
2137086523, limited by database with OID 13432
Mar 25 14:48:26 cowtn postgres[39875]: [35303-1] 2020-03-25
14:48:26.361 GMT [39875] DEBUG:  MultiXactId wrap limit is 2147483648,
limited by database with OID 13432
Mar 25 14:48:26 cowtn postgres[39875]: [35304-1] 2020-03-25
14:48:26.361 GMT [39875] DEBUG:  MultiXact member stop limit is now
4294914944 based on MultiXact 1

postgres=# SELECT datname
    , oid
    , age(datfrozenxid)
    , current_setting('autovacuum_freeze_max_age')
FROM pg_database;
  datname  |   oid    |    age    | current_setting
-----------+----------+-----------+-----------------
 postgres  |    13432 | 202588645 | 200000000
 template1 |        1 | 152588645 | 200000000
 template0 |    13431 |  87271781 | 200000000
 feedi     | 32178861 |  87271781 | 200000000

Here is the output from the "What is" queries referenced:

postgres=# SELECT datname, age(datfrozenxid), datfrozenxid FROM
pg_database ORDER BY age(datfrozenxid) DESC LIMIT 1;
 datname  |    age    | datfrozenxid
----------+-----------+--------------
 postgres | 202773709 |   4284570172


 postgres=# SELECT oid::regclass, age(relfrozenxid), relfrozenxid FROM
pg_class WHERE relfrozenxid <> 0 ORDER BY age(relfrozenxid) DESC LIMIT
1;
    oid    |    age    | relfrozenxid
-----------+-----------+--------------
 pg_authid | 202793549 |   4284570172


 postgres=# SELECT pid, backend_xmin, age(backend_xmin) FROM
pg_stat_activity WHERE backend_xmin <> 0 ORDER BY age(backend_xmin)
DESC LIMIT 3;
  pid  | backend_xmin | age
-------+--------------+------
 17032 |    192412343 | 7199
 17033 |    192412343 | 7199
 52320 |    192419542 |    0
(3 rows)


postgres=# SELECT pid, backend_xmin, age(backend_xmin) FROM
pg_stat_replication WHERE backend_xmin <> 0 ORDER BY age(backend_xmin)
DESC LIMIT 3;
  pid  | backend_xmin | age
-------+--------------+------
 17032 |    192434622 | 2004
 17033 |    192434622 | 2004
(2 rows)


postgres=# SELECT slot_name, xmin, age(xmin), catalog_xmin,
age(catalog_xmin) FROM pg_replication_slots WHERE xmin <> 0 OR
catalog_xmin <> 0 ORDER BY greatest(age(xmin), age(catalog_xmin)) DESC
LIMIT 3;
 slot_name | xmin | age | catalog_xmin | age
-----------+------+-----+--------------+-----
(0 rows)


postgres=# SELECT gid, database, transaction FROM pg_prepared_xacts
ORDER BY age(transaction) LIMIT 3;
 gid | database | transaction
-----+----------+-------------
(0 rows)

Let me know if there's anything else useful I can provide.

Thanks-
Justin

On Tue, Mar 24, 2020 at 2:43 PM Andres Freund <andres@anarazel.de> wrote:
>
> Hi,
>
> On 2020-03-24 15:12:38 +0900, Michael Paquier wrote:
> > > Well, there's no logging of autovacuum launchers that don't do anything
> > > due to the "skipping redundant" logic, with normal log level. If somehow
> > > the horizon logic of autovacuum workers gets out of whack with what
> > > vacuumlazy.c does, then you'd not get any vacuums. But a usage level
> > > triggered analyze could still happen on such a table, I think.
> >
> > What surprised me the most is that the same table happened to be
> > analyzed again and again after the launcher began its blackout.
>
> Well, if there's an issue with the "redundant" logic, that would be a
> not too surprising outcome. It's quite plausible that one or two tables
> in the database would get enough changes to occasionally need to be
> analyzed. If the workload is steady, that could e.g. work out to every
> ~17 minutes. All tables that autovacuum things are not wraparound
> threatened will be skipped, but ones that are will get both vacuum and
> analyze queued. The redundant logic could then entirely skip all
> vacuums - but there's no equivalent for analyze.
>
> > > While looking at this issue I found a few problems, btw. That seems more
> > > like a -hackers discussion, so I started:
> > > https://postgr.es/m/20200323235036.6pje6usrjjx22zv3%40alap3.anarazel.de
> >
> > Yes, let's discuss there.
>
> Cool. Would also be good if you could expand on the thread introducing
> the "redundant" logic.
>
> Greetings,
>
> Andres Freund