Date: Tue, 24 Mar 2020 14:26:06 +0900
From: Michael Paquier <michael@paquier.xyz>
To: Andres Freund <andres@anarazel.de>
Cc: Julien Rouhaud <rjuju123@gmail.com>, Justin King <kingpin867@gmail.com>,
	pgsql-general@lists.postgresql.org, kgrittn@gmail.com
Subject: Re: PG12 autovac issues
Message-ID: <20200324052606.GE1836@paquier.xyz>
References: 
 <CAE39h23RTX1jkYjWc5tccv34HwwraizaCUxOmdQdPM+Zt5-2Qg@mail.gmail.com>
 <20200319223520.2mnjt6l3yybgnd77@alap3.anarazel.de>
 <CAE39h22XLA7A=05RezvcTmEp=A369vRScToP5iLdTwArKiAuoA@mail.gmail.com>
 <20200319235626.wz4b57hbhuuy4w7j@alap3.anarazel.de>
 <CAE39h23xR9F8qbo5vj9+KL1nFnnTaYJrFde0BtWczQy_+De39Q@mail.gmail.com>
 <20200320190317.gdxwzexdfutymqs6@alap3.anarazel.de>
 <20200323152247.GB52612@nol>
 <20200323162303.s7ay5hjdvimtkz6u@alap3.anarazel.de>
 <20200323194725.GC52612@nol>
 <20200323200051.qzyqvnips7o3ai4g@alap3.anarazel.de>
MIME-Version: 1.0
Content-Type: multipart/signed; micalg=pgp-sha512;
	protocol="application/pgp-signature"; boundary="/QKKmeG/X/bPShih"
Content-Disposition: inline
In-Reply-To: <20200323200051.qzyqvnips7o3ai4g@alap3.anarazel.de>
Precedence: bulk


--/QKKmeG/X/bPShih
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
Content-Transfer-Encoding: quoted-printable

On Mon, Mar 23, 2020 at 01:00:51PM -0700, Andres Freund wrote:
> On 2020-03-23 20:47:25 +0100, Julien Rouhaud wrote:
>>> - relfrozenxid, age(relfrozenxid) for the oldest table in the oldest da=
tabase
>>>   SELECT oid::regclass, age(relfrozenxid), relfrozenxid FROM pg_class W=
HERE relfrozenxid <> 0 ORDER BY age(relfrozenxid) DESC LIMIT 1;
>>=20
>> The vm has been trashed since, and I don't have that level of detail ava=
ilable
>> in the gathered stats unfortunately (and the available information I hav=
e is a
>> little bit messy, sorry for that).
>>=20
>>> - Oldest backend xmin
>>>   SELECT pid, backend_xmin, age(backend_xmin) FROM pg_stat_activity WHE=
RE backend_xmin <> 0 ORDER BY age(backend_xmin) DESC LIMIT 3;
>>> - oldest replication xmin:
>>>   SELECT pid, backend_xmin, age(backend_xmin) FROM pg_stat_replication =
WHERE backend_xmin <> 0 ORDER BY age(backend_xmin) DESC LIMIT 3;
>>> - oldest slot xmin:
>>>   SELECT slot_name, xmin, age(xmin), catalog_xmin, age(catalog_xmin) FR=
OM pg_replication_slots WHERE xmin <> 0 OR catalog_xmin <> 0 ORDER BY great=
est(age(xmin), age(catalog_xmin)) DESC LIMIT 3;
>>> - oldest prepared transaction (unfortunately xmin not available)
>>>   SELECT gid, database, transaction FROM pg_prepared_xacts ORDER BY age=
(transaction) LIMIT 3;
>>=20
>> I have output from this query: https://github.com/OPMDG/check_pgactivity=
/blob/oldest_xmin/check_pgactivity#L5669-L5732
>> (which may be dumb).  Here are the non-null rows after 8AM GMT+1:

This stuff does not use 2PC and logical slots (there is one physical
slot for a WAL archiver), but we got a dump of pg_stat_activity.
Grepping more info about the evolution of pg_database and pg_class is
on our list.

> Could you share what the config of the server was?

Nothing really fancy:
- autovacuum_vacuum_cost_delay to 2ms (default of v12, but we used it
in v11 as well).
- autovacuum_naptime =3D 15s
- autovacuum_max_workers =3D 6
- log_autovacuum_min_duration =3D 0

>>> In that case you'd likely see DEBUG1 output, right? Did you try running
>>> with that?
>>=20
>> That's unfortunately not an option, as while the issue is reproducible, =
it
>> happens after roughly 16h with an average of 6.5ktps, and we definitely =
don't
>> have enough disk space for that amount of logs.  We'll try next time wit=
h a
>> recompiled version with the DEBUG1 promoted to WARNING, and maybe other =
elog.
>=20
> You wouldn't need to run it with DEBUG1 the whole time, you could just
> change the config and reload config once you hit the issue.

Sure, though it would reduce the window when the cluster is still up
and running.  One option that we have is just to increase the elevel
=66rom DEBUG1 to WARNING for the log added in 2aa6e33 to keep the amount
of logs reduced without losing information, and we have no issue to
do runs with custom patches.

>> Not for now, because it's hard to be around for the ~ 90min interval the=
 system
>> stays alive after atuvacuum get stuck, especially since it's a weekend b=
ench.

Yeah, our room is very limited here.  I would likely not ne able to do
that, or I would just get very lucky with my timezone.  Not sure for
Julien.

>>> It sounds like what might be happening is that you have something
>>> holding back the "oldest needed transaction" horizon. Before
>>> 2aa6e331ead7, if the xmin horizon hasn't increased, there'd be repeated
>>> vacuums unable to increase the horizon, but afterwards they'll all
>>> immediately exit without any messages.
>>=20
>> The xmin horizon is increasing AFAICS.  Grepping the autovacuum logs, I =
can see
>> for the 08:00 AM UTC - 08:59 AM UTC interval the oldest xmin going from
>> 200069684 to 210363848.  E.g.:
>=20
> Which database is this on?

In this case this was the database used by the application, FWIW.  But
I can see from those logs that it kept increasing for all the other
databases, like postgres or template1 when this set of aggressive jobs
happened.

>> 266621:2020-03-14 08:49:59.945 UTC LOG:  automatic aggressive vacuum to =
prevent wraparound of table "pg_toast.pg_toast_27712": index scans: 0
>> 266622-	pages: 0 removed, 0 remain, 0 skipped due to pins, 0 skipped fro=
zen
>> 266623-	tuples: 0 removed, 0 remain, 0 are dead but not yet removable, o=
ldest xmin: 209635953
>> [...]
>=20
> Do you have any non-toast ones?

Yep, this includes catalogs and normal tables, based on the logs all
the relations triggered aggressive and anti-wraparound jobs.

>>> I wonder if what might be happening is that we're somehow missed/failed
>>> to update relfrozenxid and/or datfrozenxid. If you manually vacuum some
>>> table in the oldest database, but that is *NOT* the oldest table itself,
>>> does the problem "resolve" itself?
>>=20
>> I'll also add pg_class snapshot for next time we run the bench.  I'm not=
 sure
>> if we'll be able to catch the 1h45 interval when the system stays alive
>> after the issue though.
>=20
> Could you just script something to stop the benchmark once the disk is
> 90% full or so?

Hmm.  I think that this one is possible still tricky.  There are some
alarms in place in this system.

> Did you see any errors / fatals around the time autovacuum stopped
> working?

Before going rogue (we are not sure if autovacuum didn't launch any
workers or if the workers were spawned and exited early as we did not
capture any worker information in pg_stat_activity), we saw a bunch of
aggressive wraparound jobs.  Even after that, we have traces in the
logs of one autovacuum analyze happening at equal interval of time (17
minutes) on one single table, which is...  Er...  uncommon to say the
least.
--
Michael

--/QKKmeG/X/bPShih
Content-Type: application/pgp-signature; name="signature.asc"

-----BEGIN PGP SIGNATURE-----

iQIzBAABCgAdFiEEG72nH6vTowiyblFKnvQgOdbyQH0FAl55me4ACgkQnvQgOdby
QH1OjBAAi8R22N8D94CkFoD4KxT306P2qajVTRmFMPi6v63nngp/AQ9dwlCU4IHz
zr/O1StEKgel3qimPQK2uAGhL9Tth4A/t3WSrz5U8OIK9FZ6QY63hnd9NBTTmO6e
VurussiMZ5Aj9P0r+EZV+QllLeeB3X3VW+vx5I/LgsXXmE9U9x7aWbWNXqRtkKfW
beKa4yQ3NIPBooNBVc59eY4/8DUP4qT3UDHn+0YqDnf+diy/N3eXh6P9P/WszW8J
a90gmRlKpCbZBhg4E4ODdNt740Eq25YPdM1i+FK2wXb7JomsChg3KFH1ZU4iecg6
JrRNxGGiozggJgnd2zLqObfv5i0MA/rjXjn/6w5gQXxRVIz8CEX2VuOdmJ4PLhtG
+8oTYsXvkQjfG7QcRDqlI7vtK0WZWEwgR0751zqsyIRfDjrlh9M4YVGYT0XSqVjF
euJiisge+pmmjp6y2EnjUqepw8Z7/UdYTttKIY2mH/QKTsRFSKnH8A215H2Zp7uA
tQERsekaLx9GoW3xS6eKRGOg/whtqGHebs2pe3kYdE0NNDfR2DAE0iUoxOlU9pI3
qkTONsUDePLj/LmrI2UI6KD00DRg88bE/Ub9CXZ7jl3Ue86/VJq8jmgLjGpxtYkF
BGfwxEqaivlnL0M2oxRWOOsakB8sf/5EDB+b0sPhsCo2LV70tLY=
=FLDr
-----END PGP SIGNATURE-----

--/QKKmeG/X/bPShih--