From: Tom Lane <tgl@sss.pgh.pa.us>
To: Amit Kapila <amit.kapila16@gmail.com>
cc: Tomas Vondra <tomas.vondra@2ndquadrant.com>,
        Dilip Kumar <dilipbalaut@gmail.com>, Erik Rijkers <er@xs4all.nl>,
        Jeff Janes <jeff.janes@gmail.com>,
        Kuntal Ghosh <kuntalghosh.2007@gmail.com>,
        Michael Paquier <michael@paquier.xyz>,
        Peter Eisentraut <peter.eisentraut@2ndquadrant.com>,
        PostgreSQL Hackers <pgsql-hackers@postgresql.org>
Subject: Re: PATCH: logical_work_mem and logical streaming of large
 in-progress transactions
In-reply-to: 
 <CAA4eK1K5HAjLgmeBiaKqUX2XTs8hD9FAaxTt2pm-Zq=0r4rLjA@mail.gmail.com>
References: 
 <CAA4eK1JpDd8gxf4cB6nAHOq39N7kvC=O7-b-1ghALeuipb4Y3Q@mail.gmail.com>
 <CAA4eK1+do8Fdb2q8jDCdJPZCuEzkvsv2STc9LFNCBoFOKUd5HQ@mail.gmail.com>
 <CAFiTN-sfu1S3OaZiiUXXmK_Kz4ZuhwqTz-ULxiknzEdz_3S5iQ@mail.gmail.com>
 <CAA4eK1+Myjd35YRc8Swf4b+HzgU2p5N9OPAB4a7xCsmEiVjHGw@mail.gmail.com>
 <CAA4eK1L_336h=HNeBQVqxiDUvLm3L3bt5n4dtWXrC=wCc7uRZA@mail.gmail.com>
 <CAA4eK1L+O1iFRnFa269XonbZu=o259YvGQNDrVFejW6uZspaAA@mail.gmail.com>
 <CAFiTN-sqstN07dAd7bg66tx1OgbZJqmQT0uf7B33eEnX+Vj-zA@mail.gmail.com>
 <CAA4eK1LEEhtTEnDnrWcZryOGBdhi_6X4h2MJaFgbCo5+EhRBCQ@mail.gmail.com>
 <CAFiTN-s1Mn-c7d_JD0c11JuF-GDRSJTofKr5h6=+4Ob1oJb7zg@mail.gmail.com>
 <CAA4eK1LCFVPGP21AjEBzLhSpgVHzO7ZTmpAE+a46eCLAGRgesg@mail.gmail.com>
 <20200909084353.pncuclpbwlr7vylh@development>
 <CAA4eK1K8L2reu+EtG0ZHnAPSBX5kj658uz7sa_xDRSLD9CWF7Q@mail.gmail.com>
 <CAA4eK1K5HAjLgmeBiaKqUX2XTs8hD9FAaxTt2pm-Zq=0r4rLjA@mail.gmail.com>
Comments: In-reply-to Amit Kapila <amit.kapila16@gmail.com>
	message dated "Sat, 12 Sep 2020 17:17:13 +0530"
MIME-Version: 1.0
Content-Type: text/plain; charset="us-ascii"
Content-ID: <904372.1600033123.1@sss.pgh.pa.us>
Content-Transfer-Encoding: quoted-printable
Date: Sun, 13 Sep 2020 17:38:43 -0400
Message-ID: <904373.1600033123@sss.pgh.pa.us>
Precedence: bulk

Amit Kapila <amit.kapila16@gmail.com> writes:
> Pushed.

Observe the following reports:

https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=3Didiacanthus&dt=3D=
2020-09-13%2016%3A54%3A03
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=3Ddesmoxytes&dt=3D=
2020-09-10%2009%3A08%3A03
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=3Dkomodoensis&dt=3D=
2020-09-05%2020%3A22%3A02
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=3Ddragonet&dt=3D20=
20-09-04%2001%3A52%3A03
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=3Ddragonet&dt=3D20=
20-09-03%2020%3A54%3A04

These are all on HEAD, and all within the last ten days, and I see
nothing comparable in any branch before that.  So it's hard to avoid
the conclusion that somebody broke something about ten days ago.

None of these animals provided gdb backtraces; but we do have a built-in
trace from several, and they all look like pgoutput.so is trying to
list_free() garbage, somewhere inside a relcache invalidation/rebuild
scenario:

TRAP: FailedAssertion("list->length > 0", File: "/home/bf/build/buildfarm-=
idiacanthus/HEAD/pgsql.build/../pgsql/src/backend/nodes/list.c", Line: 68)
postgres: publisher: walsender bf [local] idle(ExceptionalCondition+0x57)[=
0x9081f7]
postgres: publisher: walsender bf [local] idle[0x6bcc70]
postgres: publisher: walsender bf [local] idle(list_free+0x11)[0x6bdc01]
/home/bf/build/buildfarm-idiacanthus/HEAD/pgsql.build/tmp_install/home/bf/=
build/buildfarm-idiacanthus/HEAD/inst/lib/postgresql/pgoutput.so(+0x35d8)[=
0x7fa4c5a6f5d8]
postgres: publisher: walsender bf [local] idle(LocalExecuteInvalidationMes=
sage+0x15b)[0x8f0cdb]
postgres: publisher: walsender bf [local] idle(ReceiveSharedInvalidMessage=
s+0x4b)[0x7bca0b]
postgres: publisher: walsender bf [local] idle(LockRelationOid+0x56)[0x7c1=
9e6]
postgres: publisher: walsender bf [local] idle(relation_open+0x1c)[0x4a2d0=
c]
postgres: publisher: walsender bf [local] idle(table_open+0x6)[0x524486]
postgres: publisher: walsender bf [local] idle[0x9017f2]
postgres: publisher: walsender bf [local] idle[0x8fabd4]
postgres: publisher: walsender bf [local] idle[0x8fa58a]
postgres: publisher: walsender bf [local] idle(RelationCacheInvalidateEntr=
y+0xaf)[0x8fbdbf]
postgres: publisher: walsender bf [local] idle(LocalExecuteInvalidationMes=
sage+0xec)[0x8f0c6c]
postgres: publisher: walsender bf [local] idle(ReceiveSharedInvalidMessage=
s+0xcb)[0x7bca8b]
postgres: publisher: walsender bf [local] idle(LockRelationOid+0x56)[0x7c1=
9e6]
postgres: publisher: walsender bf [local] idle(relation_open+0x1c)[0x4a2d0=
c]
postgres: publisher: walsender bf [local] idle(table_open+0x6)[0x524486]
postgres: publisher: walsender bf [local] idle[0x8ee8b0]

010_truncate.pl itself hasn't changed meaningfully in a good long time.
However, I see that 464824323 added a whole boatload of code to
pgoutput.c, and the timing is right for that commit to be the culprit,
so that's what I'm betting on.

Probably this requires a relcache inval at the wrong time;
although we have recent passes from CLOBBER_CACHE_ALWAYS animals,
so that can't be the whole triggering condition.  I wonder whether
it is relevant that all of the complaining animals are JIT-enabled.

			regards, tom lane