Обсуждение: logical decoding / rewrite map vs. maxAllocatedDescs

Поиск

Список

Период

Сортировка

logical decoding / rewrite map vs. maxAllocatedDescs

От

Tomas Vondra

Дата:

09 августа 2018 г., 23:31:00

Hi,

While investigating an issue with rewrite maps in logical decoding, I 
found it's pretty darn trivial to hit this:

     ERROR:  53000: exceeded maxAllocatedDescs (492) while trying to open
     file "pg_logical/mappings/map-4000-4eb-1_60DE1E08-5376b5-537c6b"

This happens because we seem to open the mapping files and keep them 
open until the next checkpoint, at which point we fsync + close.

I suppose there are reasons why it's done this way, and admittedly the 
test that happens to trigger this is a bit extreme (essentially running 
pgbench concurrently with 'vacuum full pg_class' in a loop). I'm not 
sure it's extreme enough to deem it not an issue, because people using 
many temporary tables often deal with bloat by doing frequent vacuum 
full on catalogs.

Furthermore, the situation is made worse by opening the same file 
repeatedly, under different file descriptor.

I've added elog(LOG) to OpenTransientFile and CloseTransientFile - see 
the attached file.log, which is filtered to a single process. The 'cnt' 
field is showing numAllocatedDescs. There are 500 calls to 
OpenTransientFile, but only 8 calls to CloseTransientFile (all of them 
for pg_filenode.map).

But each of the mapping files is opened 9x, so we run out of file 
descriptors 10x faster. Moreover, I'm pretty sure simply increasing the 
file descriptor limit is not a solution - we'll simply end up opening 
the files over and over until hitting it again.

But wait, there's more - what happens after hitting the limit? We 
restart the decoding process, and end up getting this:

     ERROR:  53000: exceeded maxAllocatedDescs (492) while trying to open
     file "pg_logical/mappings/map-4000-4eb-1_60DE1E08-5376b5-537c6b"
     LOCATION:  OpenTransientFile, fd.c:2161
     LOG:  00000: starting logical decoding for slot "s"
     DETAIL:  streaming transactions committing after 1/6097DD48, reading
     WAL from 1/60275848
     LOCATION:  CreateDecodingContext, logical.c:414
     LOG:  00000: logical decoding found consistent point at 1/60275848
     DETAIL:  Logical decoding will begin using saved snapshot.
     LOCATION:  SnapBuildRestore, snapbuild.c:1872
     ERROR:  XX000: subtransaction logged without previous top-level txn
     record
     LOCATION:  ReorderBufferAssignChild, reorderbuffer.c:790
     LOG:  00000: starting logical decoding for slot "s"
     DETAIL:  streaming transactions committing after 1/60988088, reading
     WAL from 1/60275848
     LOCATION:  CreateDecodingContext, logical.c:414
     LOG:  00000: logical decoding found consistent point at 1/60275848
     DETAIL:  Logical decoding will begin using saved snapshot.
     LOCATION:  SnapBuildRestore, snapbuild.c:1872
     ERROR:  XX000: subtransaction logged without previous top-level txn
     record
     LOCATION:  ReorderBufferAssignChild, reorderbuffer.c:790

I'd say this implies the "can't open file" is handled in a way that 
corrupts the mapping files, making it impossible to restart the 
decoding. AFAICS the only option at this point is to drop the 
subscription and start over.

I think the right solution here is (a) making sure we don't needlessly 
open the same mapping file over and over, (b) closing the files sooner, 
instead of waiting for the next checkpoint. I guess a small local cache 
of file descriptors would do both things.

Not sure about the error handling. Even if we get rid of the file 
descriptor limit issue, I guess there are other ways why this we can 
fail here, so we probably need to improve that too.

regards

-- 
Tomas Vondra                  http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Вложения

file.log

Re: logical decoding / rewrite map vs. maxAllocatedDescs

От

Tom Lane

Дата:

09 августа 2018 г., 23:42:17

Tomas Vondra <tomas.vondra@2ndquadrant.com> writes:
> While investigating an issue with rewrite maps in logical decoding, I 
> found it's pretty darn trivial to hit this:
>      ERROR:  53000: exceeded maxAllocatedDescs (492) while trying to open
>      file "pg_logical/mappings/map-4000-4eb-1_60DE1E08-5376b5-537c6b"

> This happens because we seem to open the mapping files and keep them 
> open until the next checkpoint, at which point we fsync + close.

It sounds like whoever wrote that code was completely impervious to the
API spec for AllocateFile():

 * Note that files that will be open for any significant length of time
 * should NOT be handled this way, since they cannot share kernel file
 * descriptors with other files; there is grave risk of running out of FDs
 * if anyone locks down too many FDs.

Perhaps these files should be accessed through fd.c's VFD infrastructure
rather than ignoring it.  Reinventing it is especially not the way to go.

> Furthermore, the situation is made worse by opening the same file 
> repeatedly, under different file descriptor.

That's just stupid :-(

Note that the limit on maxAllocatedDescs is based on the kernel limit
on how many files a process can have open, so assuming you can increase
it is not going to end well.

            regards, tom lane

Re: logical decoding / rewrite map vs. maxAllocatedDescs

От

Alvaro Herrera

Дата:

09 августа 2018 г., 23:47:46

On 2018-Aug-09, Tomas Vondra wrote:

> I suppose there are reasons why it's done this way, and admittedly the test
> that happens to trigger this is a bit extreme (essentially running pgbench
> concurrently with 'vacuum full pg_class' in a loop). I'm not sure it's
> extreme enough to deem it not an issue, because people using many temporary
> tables often deal with bloat by doing frequent vacuum full on catalogs.

Actually, it seems to me that ApplyLogicalMappingFile is just leaking
the file descriptor for no good reason.  There's a different
OpenTransientFile call in ReorderBufferRestoreChanges that is not
intended to be closed immediately, but the other one seems a plain bug,
easy enough to fix.

> But wait, there's more - what happens after hitting the limit? We restart
> the decoding process, and end up getting this:
> 
>     ERROR:  53000: exceeded maxAllocatedDescs (492) while trying to open
>     file "pg_logical/mappings/map-4000-4eb-1_60DE1E08-5376b5-537c6b"
>     LOCATION:  OpenTransientFile, fd.c:2161
>     LOG:  00000: starting logical decoding for slot "s"
>     DETAIL:  streaming transactions committing after 1/6097DD48, reading
>     WAL from 1/60275848
>     LOCATION:  CreateDecodingContext, logical.c:414
>     LOG:  00000: logical decoding found consistent point at 1/60275848
>     DETAIL:  Logical decoding will begin using saved snapshot.
>     LOCATION:  SnapBuildRestore, snapbuild.c:1872
>     ERROR:  XX000: subtransaction logged without previous top-level txn
>     record

Hmm, I wonder if we introduced some bug in f49a80c481f7.

> I'd say this implies the "can't open file" is handled in a way that corrupts
> the mapping files, making it impossible to restart the decoding. AFAICS the
> only option at this point is to drop the subscription and start over.

Wow, that seems pretty serious.  Clearly that's a different bug that
must be fixed.

-- 
Álvaro Herrera                https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Re: logical decoding / rewrite map vs. maxAllocatedDescs

От

Alvaro Herrera

Дата:

09 августа 2018 г., 23:58:46

On 2018-Aug-09, Tom Lane wrote:

> It sounds like whoever wrote that code was completely impervious to the
> API spec for AllocateFile():
> 
>  * Note that files that will be open for any significant length of time
>  * should NOT be handled this way, since they cannot share kernel file
>  * descriptors with other files; there is grave risk of running out of FDs
>  * if anyone locks down too many FDs.
> 
> Perhaps these files should be accessed through fd.c's VFD infrastructure
> rather than ignoring it.  Reinventing it is especially not the way to go.

Ah, right.  Maybe ReorderBufferRestoreChanges should use
PathNameOpenFile / FileRead ...

-- 
Álvaro Herrera                https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Re: logical decoding / rewrite map vs. maxAllocatedDescs

От

Tomas Vondra

Дата:

09 августа 2018 г., 23:58:57


On 08/09/2018 07:47 PM, Alvaro Herrera wrote:
> On 2018-Aug-09, Tomas Vondra wrote:
> 
>> I suppose there are reasons why it's done this way, and admittedly the test
>> that happens to trigger this is a bit extreme (essentially running pgbench
>> concurrently with 'vacuum full pg_class' in a loop). I'm not sure it's
>> extreme enough to deem it not an issue, because people using many temporary
>> tables often deal with bloat by doing frequent vacuum full on catalogs.
> 
> Actually, it seems to me that ApplyLogicalMappingFile is just leaking
> the file descriptor for no good reason.  There's a different
> OpenTransientFile call in ReorderBufferRestoreChanges that is not
> intended to be closed immediately, but the other one seems a plain bug,
> easy enough to fix.
> 
>> But wait, there's more - what happens after hitting the limit? We restart
>> the decoding process, and end up getting this:
>>
>>      ERROR:  53000: exceeded maxAllocatedDescs (492) while trying to open
>>      file "pg_logical/mappings/map-4000-4eb-1_60DE1E08-5376b5-537c6b"
>>      LOCATION:  OpenTransientFile, fd.c:2161
>>      LOG:  00000: starting logical decoding for slot "s"
>>      DETAIL:  streaming transactions committing after 1/6097DD48, reading
>>      WAL from 1/60275848
>>      LOCATION:  CreateDecodingContext, logical.c:414
>>      LOG:  00000: logical decoding found consistent point at 1/60275848
>>      DETAIL:  Logical decoding will begin using saved snapshot.
>>      LOCATION:  SnapBuildRestore, snapbuild.c:1872
>>      ERROR:  XX000: subtransaction logged without previous top-level txn
>>      record
> 
> Hmm, I wonder if we introduced some bug in f49a80c481f7.
> 

That's possible. I'm running on f85537a88d, i.e. with f49a80c481f7.

>> I'd say this implies the "can't open file" is handled in a way that corrupts
>> the mapping files, making it impossible to restart the decoding. AFAICS the
>> only option at this point is to drop the subscription and start over.
> 
> Wow, that seems pretty serious.  Clearly that's a different bug that
> must be fixed.
> 

Yep.

regards

-- 
Tomas Vondra                  http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Re: logical decoding / rewrite map vs. maxAllocatedDescs

От

Tomas Vondra

Дата:

11 августа 2018 г., 02:57:57


On 08/09/2018 07:47 PM, Alvaro Herrera wrote:
> On 2018-Aug-09, Tomas Vondra wrote:
> 
>> I suppose there are reasons why it's done this way, and admittedly the test
>> that happens to trigger this is a bit extreme (essentially running pgbench
>> concurrently with 'vacuum full pg_class' in a loop). I'm not sure it's
>> extreme enough to deem it not an issue, because people using many temporary
>> tables often deal with bloat by doing frequent vacuum full on catalogs.
> 
> Actually, it seems to me that ApplyLogicalMappingFile is just leaking
> the file descriptor for no good reason.  There's a different
> OpenTransientFile call in ReorderBufferRestoreChanges that is not
> intended to be closed immediately, but the other one seems a plain bug,
> easy enough to fix.
> 

Indeed. Adding a CloseTransientFile to ApplyLogicalMappingFile solves
the issue with hitting maxAllocatedDecs. Barring objections I'll commit
this shortly.

>> But wait, there's more - what happens after hitting the limit? We restart
>> the decoding process, and end up getting this:
>>
>>     ERROR:  53000: exceeded maxAllocatedDescs (492) while trying to open
>>     file "pg_logical/mappings/map-4000-4eb-1_60DE1E08-5376b5-537c6b"
>>     LOCATION:  OpenTransientFile, fd.c:2161
>>     LOG:  00000: starting logical decoding for slot "s"
>>     DETAIL:  streaming transactions committing after 1/6097DD48, reading
>>     WAL from 1/60275848
>>     LOCATION:  CreateDecodingContext, logical.c:414
>>     LOG:  00000: logical decoding found consistent point at 1/60275848
>>     DETAIL:  Logical decoding will begin using saved snapshot.
>>     LOCATION:  SnapBuildRestore, snapbuild.c:1872
>>     ERROR:  XX000: subtransaction logged without previous top-level txn
>>     record
> 
> Hmm, I wonder if we introduced some bug in f49a80c481f7.
> 

Not sure. I've tried reproducing it both on b767b3f2e5b7 (that's f49...
in REL_10_STABLE branch) and 09879f7536350 (that's the commit
immediately before it), and I can't reproduce it for some reason. I'll
try on Monday on the same laptop I used before (it's in the office, so I
can't try now).

But while running the tests on this machine, I repeatedly got pgbench
failures like this:

client 2 aborted in command 0 of script 0; ERROR:  could not read block
3 in file "base/16384/24573": read only 0 of 8192 bytes

That kinda reminds me the issues we're observing on some buildfarm
machines, I wonder if it's the same thing.

I suppose relfilenode 24573 is pg_class, which is the only table I'm
running vacuum full on here.


regards

-- 
Tomas Vondra                  http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Re: logical decoding / rewrite map vs. maxAllocatedDescs

От

Andres Freund

Дата:

11 августа 2018 г., 03:13:40

On 2018-08-10 22:57:57 +0200, Tomas Vondra wrote:
> 
> 
> On 08/09/2018 07:47 PM, Alvaro Herrera wrote:
> > On 2018-Aug-09, Tomas Vondra wrote:
> > 
> >> I suppose there are reasons why it's done this way, and admittedly the test
> >> that happens to trigger this is a bit extreme (essentially running pgbench
> >> concurrently with 'vacuum full pg_class' in a loop). I'm not sure it's
> >> extreme enough to deem it not an issue, because people using many temporary
> >> tables often deal with bloat by doing frequent vacuum full on catalogs.
> > 
> > Actually, it seems to me that ApplyLogicalMappingFile is just leaking
> > the file descriptor for no good reason.  There's a different
> > OpenTransientFile call in ReorderBufferRestoreChanges that is not
> > intended to be closed immediately, but the other one seems a plain bug,
> > easy enough to fix.
> > 
> 
> Indeed. Adding a CloseTransientFile to ApplyLogicalMappingFile solves
> the issue with hitting maxAllocatedDecs. Barring objections I'll commit
> this shortly.

Yea, that's clearly a bug. I've not seen a patch, so I can't quite
formally sign off, but it seems fairly obvious.


> But while running the tests on this machine, I repeatedly got pgbench
> failures like this:
> 
> client 2 aborted in command 0 of script 0; ERROR:  could not read block
> 3 in file "base/16384/24573": read only 0 of 8192 bytes
> 
> That kinda reminds me the issues we're observing on some buildfarm
> machines, I wonder if it's the same thing.

Oooh, that's interesting! What's the precise recipe that gets you there?

Greetings,

Andres Freund

Re: logical decoding / rewrite map vs. maxAllocatedDescs

От

Tomas Vondra

Дата:

11 августа 2018 г., 03:59:44


On 08/10/2018 11:13 PM, Andres Freund wrote:
> On 2018-08-10 22:57:57 +0200, Tomas Vondra wrote:
>>
>>
>> On 08/09/2018 07:47 PM, Alvaro Herrera wrote:
>>> On 2018-Aug-09, Tomas Vondra wrote:
>>>
>>>> I suppose there are reasons why it's done this way, and admittedly the test
>>>> that happens to trigger this is a bit extreme (essentially running pgbench
>>>> concurrently with 'vacuum full pg_class' in a loop). I'm not sure it's
>>>> extreme enough to deem it not an issue, because people using many temporary
>>>> tables often deal with bloat by doing frequent vacuum full on catalogs.
>>>
>>> Actually, it seems to me that ApplyLogicalMappingFile is just leaking
>>> the file descriptor for no good reason.  There's a different
>>> OpenTransientFile call in ReorderBufferRestoreChanges that is not
>>> intended to be closed immediately, but the other one seems a plain bug,
>>> easy enough to fix.
>>>
>>
>> Indeed. Adding a CloseTransientFile to ApplyLogicalMappingFile solves
>> the issue with hitting maxAllocatedDecs. Barring objections I'll commit
>> this shortly.
> 
> Yea, that's clearly a bug. I've not seen a patch, so I can't quite
> formally sign off, but it seems fairly obvious.
> 
> 
>> But while running the tests on this machine, I repeatedly got pgbench
>> failures like this:
>>
>> client 2 aborted in command 0 of script 0; ERROR:  could not read block
>> 3 in file "base/16384/24573": read only 0 of 8192 bytes
>>
>> That kinda reminds me the issues we're observing on some buildfarm
>> machines, I wonder if it's the same thing.
> 
> Oooh, that's interesting! What's the precise recipe that gets you there?
> 

I don't have an exact reproducer - it's kinda rare and unpredictable,
and I'm not sure how much it depends on the environment etc. But I'm
doing this:

1) one cluster with publication (wal_level=logical)

2) one cluster with subscription to (1)

3) simple table, replicated from (1) to (2)

   -- publisher
   create table t (a serial primary key, b int, c int);
   create publication p for table t;

   -- subscriber
   create table t (a serial primary key, b int, c int);
   create subscription s CONNECTION '...' publication p;

4) pgbench inserting rows into the replicated table

   pgbench -n -c 4 -T 300 -p 5433 -f insert.sql test

5) pgbench doing vacuum full on pg_class

   pgbench -n -f vacuum.sql -T 300 -p 5433 test

And once in a while I see failures like this:

   client 0 aborted in command 0 of script 0; ERROR:  could not read
   block 3 in file "base/16384/86242": read only 0 of 8192 bytes

   client 3 aborted in command 0 of script 0; ERROR:  could not read
   block 3 in file "base/16384/86242": read only 0 of 8192 bytes

   client 2 aborted in command 0 of script 0; ERROR:  could not read
   block 3 in file "base/16384/86242": read only 0 of 8192 bytes

or this:

   client 2 aborted in command 0 of script 0; ERROR:  could not read
   block 3 in file "base/16384/89369": read only 0 of 8192 bytes

   client 1 aborted in command 0 of script 0; ERROR:  could not read
   block 3 in file "base/16384/89369": read only 0 of 8192 bytes

I suspect there's some other ingredient, e.g. some manipulation with the
subscription. Or maybe it's not needed at all and I'm just imagining things.


regards

-- 
Tomas Vondra                  http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Вложения

Re: logical decoding / rewrite map vs. maxAllocatedDescs

От

Tomas Vondra

Дата:

11 августа 2018 г., 05:55:43

On 08/10/2018 11:59 PM, Tomas Vondra wrote:
> 
> ...
> 
> I suspect there's some other ingredient, e.g. some manipulation with the
> subscription. Or maybe it's not needed at all and I'm just imagining things.
> 

Indeed, the manipulation with the subscription seems to be the key here.
I pretty reliably get the 'could not read block' error when doing this:

1) start the insert pgbench

   pgbench -n -c 4 -T 300 -p 5433 -f insert.sql test

2) start the vacuum full pgbench

   pgbench -n -f vacuum.sql -T 300 -p 5433 test

3) try to create a subscription, but with small amount of conflicting
data so that the sync fails like this:

  LOG:  logical replication table synchronization worker for
  subscription "s", table "t" has started
  ERROR:  duplicate key value violates unique constraint "t_pkey"
  DETAIL:  Key (a)=(5997542) already exists.
  CONTEXT:  COPY t, line 1
  LOG:  worker process: logical replication worker for subscription
  16458 sync 16397 (PID 31983) exited with exit code 1

4) At this point the insert pgbench (at least some clients) should have
failed with the error. If not, rinse and repeat.

This kinda explains why I've been seeing the error only occasionally,
because it only happened when I forgotten to clean the table on the
subscriber while recreating the subscription.

regards

-- 
Tomas Vondra                  http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Re: logical decoding / rewrite map vs. maxAllocatedDescs

От

Andres Freund

Дата:

11 августа 2018 г., 13:06:18

Hi,

On 2018-08-11 01:55:43 +0200, Tomas Vondra wrote:
> On 08/10/2018 11:59 PM, Tomas Vondra wrote:
> > 
> > ...
> > 
> > I suspect there's some other ingredient, e.g. some manipulation with the
> > subscription. Or maybe it's not needed at all and I'm just imagining things.
> > 
> 
> Indeed, the manipulation with the subscription seems to be the key here.
> I pretty reliably get the 'could not read block' error when doing this:
> 
> 1) start the insert pgbench
> 
>    pgbench -n -c 4 -T 300 -p 5433 -f insert.sql test
> 
> 2) start the vacuum full pgbench
> 
>    pgbench -n -f vacuum.sql -T 300 -p 5433 test
> 
> 3) try to create a subscription, but with small amount of conflicting
> data so that the sync fails like this:
> 
>   LOG:  logical replication table synchronization worker for
>   subscription "s", table "t" has started
>   ERROR:  duplicate key value violates unique constraint "t_pkey"
>   DETAIL:  Key (a)=(5997542) already exists.
>   CONTEXT:  COPY t, line 1
>   LOG:  worker process: logical replication worker for subscription
>   16458 sync 16397 (PID 31983) exited with exit code 1
> 
> 4) At this point the insert pgbench (at least some clients) should have
> failed with the error. If not, rinse and repeat.
> 
> This kinda explains why I've been seeing the error only occasionally,
> because it only happened when I forgotten to clean the table on the
> subscriber while recreating the subscription.

I'll try to reproduce this.  If you're also looking, I suspect a good
first hint would be to just change the ERROR into a PANIC and look at
the backtrace from the generated core file.

To the point that I wonder if we shouldn't just change the ERROR into a
PANIC on master (but not REL_11_STABLE), so the buildfarm gives us
feedback.  I don't think the problem can fundamentally be related to
subscriptions, given the error occurs before any subscriptions are
created in the schedule.

Greetings,

Andres Freund

Re: logical decoding / rewrite map vs. maxAllocatedDescs

От

Peter Geoghegan

Дата:

11 августа 2018 г., 13:15:25

On Sat, Aug 11, 2018 at 12:06 AM, Andres Freund <andres@anarazel.de> wrote:
> To the point that I wonder if we shouldn't just change the ERROR into a
> PANIC on master (but not REL_11_STABLE), so the buildfarm gives us
> feedback.  I don't think the problem can fundamentally be related to
> subscriptions, given the error occurs before any subscriptions are
> created in the schedule.

+1. I like that idea.


-- 
Peter Geoghegan

Re: logical decoding / rewrite map vs. maxAllocatedDescs

От

Andres Freund

Дата:

11 августа 2018 г., 13:34:15

Hi,

On 2018-08-11 01:55:43 +0200, Tomas Vondra wrote:
> On 08/10/2018 11:59 PM, Tomas Vondra wrote:
> > 
> > ...
> > 
> > I suspect there's some other ingredient, e.g. some manipulation with the
> > subscription. Or maybe it's not needed at all and I'm just imagining things.
> > 
> 
> Indeed, the manipulation with the subscription seems to be the key here.
> I pretty reliably get the 'could not read block' error when doing this:
> 
> 1) start the insert pgbench
> 
>    pgbench -n -c 4 -T 300 -p 5433 -f insert.sql test
> 
> 2) start the vacuum full pgbench
> 
>    pgbench -n -f vacuum.sql -T 300 -p 5433 test

Just to be clear: 5433 is the subscriber, right? I tried it with both,
but it's not clear what you meant with either the previous or the this
email.


> 3) try to create a subscription, but with small amount of conflicting
> data so that the sync fails like this:
> 
>   LOG:  logical replication table synchronization worker for
>   subscription "s", table "t" has started
>   ERROR:  duplicate key value violates unique constraint "t_pkey"
>   DETAIL:  Key (a)=(5997542) already exists.
>   CONTEXT:  COPY t, line 1
>   LOG:  worker process: logical replication worker for subscription
>   16458 sync 16397 (PID 31983) exited with exit code 1
> 
> 4) At this point the insert pgbench (at least some clients) should have
> failed with the error. If not, rinse and repeat.

I've run this numerous times now, and I haven't triggered it yet :/

Greetings,

Andres Freund

Re: logical decoding / rewrite map vs. maxAllocatedDescs

От

Andres Freund

Дата:

11 августа 2018 г., 13:46:25

On 2018-08-11 00:34:15 -0700, Andres Freund wrote:
> I've run this numerous times now, and I haven't triggered it yet :/

Heh, I hit it literally seconds after hitting send:

2018-08-11 00:35:52.804 PDT [2196][9/14864] LOG:  automatic analyze of table "postgres.pg_catalog.pg_depend" system
usage:CPU: user: 0.02 s, system: 0.00 s, elapsed: 0.15 s 
2018-08-11 00:36:00.391 PDT [2196][9/14866] LOG:  automatic analyze of table "postgres.public.t" system usage: CPU:
user:0.25 s, system: 0.02 s, elapsed: 7.56 s 
2018-08-11 00:36:00.399 PDT [2171][4/200412] PANIC:  could not read block 3 in file "base/12397/167946": read only 0 of
8192bytes 
2018-08-11 00:36:00.399 PDT [2171][4/200412] STATEMENT:  insert into t (b,c) values (1,1);
2018-08-11 00:36:00.410 PDT [2196][9/14868] LOG:  skipping vacuum of "pg_class" --- lock not available
2018-08-11 00:36:00.448 PDT [389][] LOG:  server process (PID 2171) was terminated by signal 6: Aborted
2018-08-11 00:36:00.448 PDT [389][] DETAIL:  Failed process was running: insert into t (b,c) values (1,1);
2018-08-11 00:36:00.448 PDT [389][] LOG:  terminating any other active server processes

Below you can find the bt full showing a bunch of nested invalidations. Looking.

#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
        set = {__val = {0, 14583431671641719254, 0, 0, 0, 0, 0, 0, 0, 0, 1296236544, 94518929497176, 1024, 0, 0, 0}}
        pid = <optimized out>
        tid = <optimized out>
        ret = <optimized out>
#1  0x00007f0de57f52f1 in __GI_abort () at abort.c:79
        save_stage = 1
        act = {__sigaction_handler = {sa_handler = 0x0, sa_sigaction = 0x0}, sa_mask = {__val = {0, 0, 0, 17399330032,
94518929499360,94518929499336, 94518929496896, 140720527947024, 94518900188034, 69, 94518929499360, 4870,
94518929496896,94518929499360, 139697663207040, 139697663189664}}, sa_flags = -444414227, sa_restorer = 0x0} 
        sigs = {__val = {32, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0}}
#2  0x000055f6e5748e0b in errfinish (dummy=0) at /home/andres/src/postgresql/src/backend/utils/error/elog.c:557
        edata = 0x55f6e5af6dc0 <errordata>
        elevel = 22
        oldcontext = 0x55f6e743c570
        econtext = 0x0
        __func__ = "errfinish"
#3  0x000055f6e55d2c0c in mdread (reln=0x55f6e7415de0, forknum=MAIN_FORKNUM, blocknum=3, buffer=0x7f0de4eb5700 "\001")
at/home/andres/src/postgresql/src/backend/storage/smgr/md.c:786 
        seekpos = 24576
        nbytes = 0
        v = 0x55f6e73a1448
        __func__ = "mdread"
#4  0x000055f6e55d5554 in smgrread (reln=0x55f6e7415de0, forknum=MAIN_FORKNUM, blocknum=3, buffer=0x7f0de4eb5700
"\001")at /home/andres/src/postgresql/src/backend/storage/smgr/smgr.c:628 
No locals.
#5  0x000055f6e5593bea in ReadBuffer_common (smgr=0x55f6e7415de0, relpersistence=112 'p', forkNum=MAIN_FORKNUM,
blockNum=3,mode=RBM_NORMAL, strategy=0x0, hit=0x7ffc0d14b7fb) at
/home/andres/src/postgresql/src/backend/storage/buffer/bufmgr.c:890
        io_start = {tv_sec = 140720527947552, tv_nsec = 94518898352892}
        io_time = {tv_sec = 72057594257389344, tv_nsec = 72197288386101248}
        bufHdr = 0x7f0de3eb76c0
        bufBlock = 0x7f0de4eb5700
        found = false
        isExtend = false
        isLocalBuf = false
        __func__ = "ReadBuffer_common"
#6  0x000055f6e55934fb in ReadBufferExtended (reln=0x7f0de627a850, forkNum=MAIN_FORKNUM, blockNum=3, mode=RBM_NORMAL,
strategy=0x0)at /home/andres/src/postgresql/src/backend/storage/buffer/bufmgr.c:664 
        hit = false
        buf = 1980
        __func__ = "ReadBufferExtended"
#7  0x000055f6e55933cf in ReadBuffer (reln=0x7f0de627a850, blockNum=3) at
/home/andres/src/postgresql/src/backend/storage/buffer/bufmgr.c:596
No locals.
#8  0x000055f6e520a530 in _bt_getbuf (rel=0x7f0de627a850, blkno=3, access=1) at
/home/andres/src/postgresql/src/backend/access/nbtree/nbtpage.c:736
        buf = 22006
        __func__ = "_bt_getbuf"
#9  0x000055f6e52091cf in _bt_getroot (rel=0x7f0de627a850, access=1) at
/home/andres/src/postgresql/src/backend/access/nbtree/nbtpage.c:282
        metabuf = 0
        metapg = 0x55f6e5216574 <_bt_preprocess_keys+326> "\351\371\004"
        metaopaque = 0x7ffc0d14b9b0
        rootbuf = 22006
        rootpage = 0x7ffc0d14b954 ""
        rootopaque = 0x55f6e743c6b0
        rootblkno = 3
        rootlevel = 1
        metad = 0x55f6e741da88
        __func__ = "_bt_getroot"
#10 0x000055f6e5210ea0 in _bt_search (rel=0x7f0de627a850, keysz=1, scankey=0x7ffc0d14c2e0, nextkey=false,
bufP=0x7ffc0d14cce4,access=1, snapshot=0x55f6e5aade80 <CatalogSnapshotData>) at
/home/andres/src/postgresql/src/backend/access/nbtree/nbtsearch.c:104
        stack_in = 0x0
        page_access = 1
#11 0x000055f6e521263d in _bt_first (scan=0x55f6e743c6b0, dir=ForwardScanDirection) at
/home/andres/src/postgresql/src/backend/access/nbtree/nbtsearch.c:1060
        rel = 0x7f0de627a850
        so = 0x55f6e74405d0
        buf = 0
        stack = 0x7ffc0d14cd20
        offnum = 0
        strat = 3
        nextkey = false
        goback = false
        startKeys = {0x55f6e743c8b8, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x7ffc0d14cd00, 0x4e55b8917, 0x55f6e743c808,
0x80,0x0, 0x0, 0x0, 0x400001d68, 0x55f6e743c8a0, 0x80, 0x55f6e743c570, 0x55f6e5785cb2 <palloc+262>, 0x0, 0x1cd0,
0x20d8,0x55f6e743c648, 0x7ffc0d14cd20, 0x55f6e5785cb2 <palloc+262>, 0x0, 0x48, 0x1305, 0x55f6e743c570, 0x55f6e743c8b8,
0x48}
        scankeys = {{sk_flags = 196608, sk_attno = 1, sk_strategy = 0, sk_subtype = 0, sk_collation = 100, sk_func =
{fn_addr= 0x55f6e52029ed <btoidcmp>, fn_oid = 356, fn_nargs = 2, fn_strict = true, fn_retset = false, fn_stats = 2
'\002',fn_extra = 0x0, fn_mcxt = 0x55f6e743c570, fn_expr = 0x0}, sk_argument = 1259}, {sk_flags = 0, sk_attno = 0,
sk_strategy= 0, sk_subtype = 0, sk_collation = 0, sk_func = {fn_addr = 0x0, fn_oid = 1296236544, fn_nargs = 0,
fn_strict= false, fn_retset = false, fn_stats = 88 'X', fn_extra = 0x1, fn_mcxt = 0x0, fn_expr = 0x0}, sk_argument =
0},{sk_flags = 0, sk_attno = 0, sk_strategy = 0, sk_subtype = 0, sk_collation = 0, sk_func = {fn_addr = 0x0, fn_oid =
3879362648,fn_nargs = 22006, fn_strict = false, fn_retset = false, fn_stats = 0 '\000', fn_extra = 0x55f6e5779cb6
<AllocSetAlloc+2370>,fn_mcxt = 0x18, fn_expr = 0x55f6e737d320}, sk_argument = 16777240}, {sk_flags = 0, sk_attno = 0,
sk_strategy= 0, sk_subtype = 0, sk_collation = 0, sk_func = {fn_addr = 0x0, fn_oid = 1296236544, fn_nargs = 0,
fn_strict= false, fn_retset = false, fn_stats = 64 '@', fn_extra = 0x8, fn_mcxt = 0x0, fn_expr = 0x0}, sk_argument =
0},{sk_flags = 1296236544, sk_attno = 0, sk_strategy = 0, sk_subtype = 3879979280, sk_collation = 22006, sk_func =
{fn_addr= 0x0, fn_oid = 0, fn_nargs = 1, fn_strict = false, fn_retset = 32, fn_stats = 148 '\224', fn_extra =
0x7f0de4c9f700,fn_mcxt = 0x7ffc0d14c480, fn_expr = 0x55f6e5218baa <_bt_check_natts+72>}, sk_argument =
140720527950960},{sk_flags = -446938903, sk_attno = 1, sk_strategy = 0, sk_subtype = 24, sk_collation = 0, sk_func =
{fn_addr= 0x55f6e577882e <wipe_mem+126>, fn_oid = 32, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 40
'(',fn_extra = 0x4d430001, fn_mcxt = 0x55f6e743c928, fn_expr = 0x20}, sk_argument = 0}, {sk_flags = 0, sk_attno = 0,
sk_strategy= 0, sk_subtype = 0, sk_collation = 0, sk_func = {fn_addr = 0x4d430000, fn_oid = 3879979304, fn_nargs =
22006,fn_strict = false, fn_retset = false, fn_stats = 32 ' ', fn_extra = 0x0, fn_mcxt = 0x0, fn_expr = 0x0},
sk_argument= 1296236545}, {sk_flags = -415604696, sk_attno = 22006, sk_strategy = 0, sk_subtype = 24, sk_collation = 0,
sk_func= {fn_addr = 0x0, fn_oid = 0, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 0 '\000', fn_extra
=0x4d430000, fn_mcxt = 0x55f6e73a6058, fn_expr = 0x8}, sk_argument = 0}, {sk_flags = 0, sk_attno = 0, sk_strategy = 0,
sk_subtype= 0, sk_collation = 0, sk_func = {fn_addr = 0x4d430000, fn_oid = 3879362600, fn_nargs = 22006, fn_strict =
false,fn_retset = false, fn_stats = 16 '\020', fn_extra = 0x0, fn_mcxt = 0x0, fn_expr = 0x55f6e599bce0}, sk_argument =
140720527952640},{sk_flags = 219466880, sk_attno = 32764, sk_strategy = 0, sk_subtype = 11, sk_collation = 0, sk_func =
{fn_addr= 0x7ffc0d14cb10, fn_oid = 15, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 20 '\024',
fn_extra= 0x8314000100000001, fn_mcxt = 0x8314000000212ded, fn_expr = 0x55f6e5ad2cb0 <PrivateRefCountArray+16>},
sk_argument= 3847846476}, {sk_flags = 0, sk_attno = 0, sk_strategy = 0, sk_subtype = 3847845018, sk_collation = 2,
sk_func= {fn_addr = 0xffffffffffffffff, fn_oid = 2, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 32 '
',fn_extra = 0x55f600000000, fn_mcxt = 0x0, fn_expr = 0x0}, sk_argument = 140720308486144}, {sk_flags = 219465440,
sk_attno= 32764, sk_strategy = 0, sk_subtype = 0, sk_collation = 32764, sk_func = {fn_addr = 0x55f6fffffff1, fn_oid =
0,fn_nargs = 32764, fn_strict = false, fn_retset = false, fn_stats = 0 '\000', fn_extra = 0xd68, fn_mcxt =
0x55f60000000f,fn_expr = 0x55f6e599bce0}, sk_argument = 4}, {sk_flags = 0, sk_attno = 0, sk_strategy = 0, sk_subtype =
3852057829,sk_collation = 22006, sk_func = {fn_addr = 0x10d14c670, fn_oid = 0, fn_nargs = 0, fn_strict = false,
fn_retset= false, fn_stats = 64 '@', fn_extra = 0x55f6e737d320, fn_mcxt = 0x0, fn_expr = 0x0}, sk_argument =
140720527951536},{sk_flags = -448403823, sk_attno = 22006, sk_strategy = 0, sk_subtype = 219465476, sk_collation =
32764,sk_func = {fn_addr = 0xdee3eb76d8, fn_oid = 3879362624, fn_nargs = 22006, fn_strict = false, fn_retset = false,
fn_stats= 64 '@', fn_extra = 0x7ffc0d14c6d0, fn_mcxt = 0x3000000018, fn_expr = 0x7ffc0d14cd60}, sk_argument =
140720527953056},{sk_flags = 219466288, sk_attno = 32764, sk_strategy = 0, sk_subtype = 3846551929, sk_collation =
22006,sk_func = {fn_addr = 0x10d14c720, fn_oid = 219472848, fn_nargs = 32764, fn_strict = false, fn_retset = false,
fn_stats= 233 '\351', fn_extra = 0x55f6e737ee88, fn_mcxt = 0x830c00000d14c720, fn_expr = 0x7f0de3d85b80}, sk_argument =
1},{sk_flags = 15625616, sk_attno = 0, sk_strategy = 8192, sk_subtype = 219465712, sk_collation = 32764, sk_func =
{fn_addr= 0x55f6e55940dd <BufferAlloc+238>, fn_oid = 3, fn_nargs = 32525, fn_strict = false, fn_retset = false,
fn_stats= 67 'C', fn_extra = 0x0, fn_mcxt = 0xde73ad0e8, fn_expr = 0x7f7000000000}, sk_argument = 94518930136320},
{sk_flags= 48, sk_attno = 0, sk_strategy = 0, sk_subtype = 3879362680, sk_collation = 22006, sk_func = {fn_addr =
0x4d430001,fn_oid = 3879362728, fn_nargs = 22006, fn_strict = false, fn_retset = false, fn_stats = 1 '\001', fn_extra =
0x0,fn_mcxt = 0x0, fn_expr = 0x0}, sk_argument = 1296236544}, {sk_flags = -415604568, sk_attno = 22006, sk_strategy =
0,sk_subtype = 1, sk_collation = 0, sk_func = {fn_addr = 0x0, fn_oid = 0, fn_nargs = 0, fn_strict = false, fn_retset =
false,fn_stats = 0 '\000', fn_extra = 0x0, fn_mcxt = 0x0, fn_expr = 0x0}, sk_argument = 94518929678504}, {sk_flags =
219466336,sk_attno = 32764, sk_strategy = 0, sk_subtype = 3849821366, sk_collation = 22006, sk_func = {fn_addr = 0x30,
fn_oid= 3879195424, fn_nargs = 22006, fn_strict = false, fn_retset = false, fn_stats = 240 '\360', fn_extra =
0x55f6e5752d7a<FunctionCall2Coll+160>, fn_mcxt = 0x4002, fn_expr = 0x4006}, sk_argument = 219465824}, {sk_flags =
-415765464,sk_attno = 22006, sk_strategy = 0, sk_subtype = 3879201832, sk_collation = 22006, sk_func = {fn_addr = 0x0,
fn_oid= 0, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 0 '\000', fn_extra = 0x4006, fn_mcxt =
0x4002,fn_expr = 0x7ffc0d14d620}, sk_argument = 0}, {sk_flags = 0, sk_attno = 0, sk_strategy = 0, sk_subtype = 0,
sk_collation= 163584, sk_func = {fn_addr = 0x4000, fn_oid = 16386, fn_nargs = 0, fn_strict = false, fn_retset = false,
fn_stats= 192 '\300', fn_extra = 0x7f0de4ed1700, fn_mcxt = 0x10d14c8d0, fn_expr = 0xc36e3d82984}, sk_argument =
140720527952208},{sk_flags = -445281983, sk_attno = 22006, sk_strategy = 0, sk_subtype = 0, sk_collation = 1574,
sk_func= {fn_addr = 0x69c55c3600000000, fn_oid = 219466224, fn_nargs = -5170, fn_strict = 64, fn_retset = 131, fn_stats
=0 '\000', fn_extra = 0x55f6e5723c42 <int4hashfast+23>, fn_mcxt = 0x626, fn_expr = 0x7ffc0d14c960}, sk_argument =
94518899785832},{sk_flags = 1574, sk_attno = 0, sk_strategy = 0, sk_subtype = 3879362624, sk_collation = 22006, sk_func
={fn_addr = 0x0, fn_oid = 20, fn_nargs = 1574, fn_strict = false, fn_retset = false, fn_stats = 1 '\001', fn_extra =
0x55f6e73a6060,fn_mcxt = 0x18, fn_expr = 0x0}, sk_argument = 0}, {sk_flags = 8408, sk_attno = 0, sk_strategy = 0,
sk_subtype= 1296236544, sk_collation = 107, sk_func = {fn_addr = 0x7, fn_oid = 0, fn_nargs = 0, fn_strict = false,
fn_retset= false, fn_stats = 112 'p', fn_extra = 0x2100, fn_mcxt = 0x55f6e743c868, fn_expr = 0xffffffffffffffb0},
sk_argument= 131}, {sk_flags = 72, sk_attno = 0, sk_strategy = 0, sk_subtype = 3879979192, sk_collation = 22006,
sk_func= {fn_addr = 0x4d430001, fn_oid = 3879979264, fn_nargs = 22006, fn_strict = false, fn_retset = false, fn_stats =
1'\001', fn_extra = 0x0, fn_mcxt = 0x0, fn_expr = 0x0}, sk_argument = 1296236544}, {sk_flags = -414988032, sk_attno =
22006,sk_strategy = 0, sk_subtype = 1, sk_collation = 0, sk_func = {fn_addr = 0x0, fn_oid = 0, fn_nargs = 0, fn_strict
=false, fn_retset = false, fn_stats = 0 '\000', fn_extra = 0x48, fn_mcxt = 0x0, fn_expr = 0x0}, sk_argument =
94518930295040},{sk_flags = 219466912, sk_attno = 32764, sk_strategy = 0, sk_subtype = 3849821366, sk_collation =
22006,sk_func = {fn_addr = 0x48, fn_oid = 3879978352, fn_nargs = 22006, fn_strict = false, fn_retset = false, fn_stats
=0 '\000', fn_extra = 0x55f6e7442668, fn_mcxt = 0x0, fn_expr = 0x0}, sk_argument = 0}, {sk_flags = 0, sk_attno = 0,
sk_strategy= 0, sk_subtype = 1296236544, sk_collation = 0, sk_func = {fn_addr = 0x55f6e74405b8, fn_oid = 16, fn_nargs =
0,fn_strict = false, fn_retset = false, fn_stats = 0 '\000', fn_extra = 0x0, fn_mcxt = 0x0, fn_expr = 0x4d430000},
sk_argument= 94518930294424}, {sk_flags = 16, sk_attno = 0, sk_strategy = 0, sk_subtype = 0, sk_collation = 0, sk_func
={fn_addr = 0x0, fn_oid = 0, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 0 '\000', fn_extra =
0x55f6e743c7f0,fn_mcxt = 0x7ffc0d14cd60, fn_expr = 0x55f6e5779cb6 <AllocSetAlloc+2370>}, sk_argument = 40}, {sk_flags =
-414988944,sk_attno = 22006, sk_strategy = 0, sk_subtype = 4222451713, sk_collation = 0, sk_func = {fn_addr =
0x7ffc0d14cd70,fn_oid = 219467120, fn_nargs = 32764, fn_strict = false, fn_retset = false, fn_stats = 112 'p', fn_extra
=0x7ffc0d14cd70, fn_mcxt = 0x7ffc0d14cd8a, fn_expr = 0x4d430001}, sk_argument = 94518930294792}, {sk_flags = 24,
sk_attno= 0, sk_strategy = 0, sk_subtype = 0, sk_collation = 0, sk_func = {fn_addr = 0x0, fn_oid = 0, fn_nargs = 0,
fn_strict= false, fn_retset = false, fn_stats = 1 '\001', fn_extra = 0x55f6e743c8a0, fn_mcxt = 0x18, fn_expr = 0x0},
sk_argument= 0}, {sk_flags = 0, sk_attno = 0, sk_strategy = 0, sk_subtype = 1296236544, sk_collation = 0, sk_func =
{fn_addr= 0x55f6e743c900, fn_oid = 56, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 0 '\000',
fn_extra= 0x0, fn_mcxt = 0x0, fn_expr = 0x4d430000}, sk_argument = 94518930294944}} 
        notnullkeys = {{sk_flags = 0, sk_attno = 0, sk_strategy = 0, sk_subtype = 0, sk_collation = 32525, sk_func =
{fn_addr= 0x0, fn_oid = 219462368, fn_nargs = 32764, fn_strict = false, fn_retset = false, fn_stats = 32 ' ', fn_extra
=0x7ffc0d14bec8, fn_mcxt = 0x7ffc00000006, fn_expr = 0x0}, sk_argument = 3432}, {sk_flags = 6, sk_attno = 0,
sk_strategy= 0, sk_subtype = 3852235000, sk_collation = 22006, sk_func = {fn_addr = 0x0, fn_oid = 3879363928, fn_nargs
=21761, fn_strict = false, fn_retset = false, fn_stats = 253 '\375', fn_extra = 0x830c000100000001, fn_mcxt =
0x830c000000212ded,fn_expr = 0x55f6e5ad2ca0 <PrivateRefCountArray>}, sk_argument = 8512178059852}, {sk_flags =
219462288,sk_attno = 32764, sk_strategy = 0, sk_subtype = 3847845018, sk_collation = 22006, sk_func = {fn_addr = 0x0,
fn_oid= 3823855104, fn_nargs = 1981, fn_strict = false, fn_retset = false, fn_stats = 176 '\260', fn_extra =
0x55f6e5210e53<_bt_drop_lock_and_maybe_pin+128>, fn_mcxt = 0x55f6e743a5f8, fn_expr = 0x55f6e737e3a0}, sk_argument =
140720527953520},{sk_flags = 8, sk_attno = 48, sk_strategy = 0, sk_subtype = 219464144, sk_collation = 32764, sk_func =
{fn_addr= 0x7ffc0d14c110, fn_oid = 1315532320, fn_nargs = 5, fn_strict = false, fn_retset = false, fn_stats = 16
'\020',fn_extra = 0x550495020, fn_mcxt = 0x551830710, fn_expr = 0x552293220}, sk_argument = 22873827600}, {sk_flags =
1409881120,sk_attno = 5, sk_strategy = 0, sk_subtype = 1430440720, sk_collation = 5, sk_func = {fn_addr = 0x555e8f620,
fn_oid= 1461890320, fn_nargs = 5, fn_strict = false, fn_retset = false, fn_stats = 56 '8', fn_extra = 0x55f6e737e138,
fn_mcxt= 0x559b1f4a0, fn_expr = 0x55aebab90}, sk_argument = 23011120800}, {sk_flags = 1556843920, sk_attno = 5,
sk_strategy= 0, sk_subtype = 1567733920, sk_collation = 5, sk_func = {fn_addr = 0x55eab6f90, fn_oid = 1599183520,
fn_nargs= 5, fn_strict = false, fn_retset = false, fn_stats = 144 '\220', fn_extra = 0x561317ca0, fn_mcxt =
0x5626b3390,fn_expr = 0x563115ea0}, sk_argument = 23157478800}, {sk_flags = 1694137120, sk_attno = 5, sk_strategy = 0,
sk_subtype= 1714696720, sk_collation = 5, sk_func = {fn_addr = 0x566da5d20, fn_oid = 1746146320, fn_nargs = 5,
fn_strict= false, fn_retset = false, fn_stats = 32 ' ', fn_extra = 0x569f3f610, fn_mcxt = 0x56a9a2120, fn_expr =
0x56bd3d810},sk_argument = 23294772000}, {sk_flags = 1840495120, sk_attno = 5, sk_strategy = 0, sk_subtype =
1851989920,sk_collation = 5, sk_func = {fn_addr = 0x56f9cd690, fn_oid = 1883439520, fn_nargs = 5, fn_strict = false,
fn_retset= false, fn_stats = 144 '\220', fn_extra = 0x57222e3a0, fn_mcxt = 0x5735c9a90, fn_expr = 0x57402c5a0},
sk_argument= 23441734800}, {sk_flags = 1977788320, sk_attno = 5, sk_strategy = 0, sk_subtype = 1998347920, sk_collation
=5, sk_func = {fn_addr = 0x577c289a0, fn_oid = 2029797520, fn_nargs = 5, fn_strict = false, fn_retset = false, fn_stats
=32 ' ', fn_extra = 0x57ae55d10, fn_mcxt = 0x100030000, fn_expr = 0x0}, sk_argument = 94518929514432}, {sk_flags = 356,
sk_attno= 2, sk_strategy = 1, sk_subtype = 40, sk_collation = 0, sk_func = {fn_addr = 0x55f6e73a5fc0, fn_oid =
1296236545,fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 232 '\350', fn_extra = 0x1, fn_mcxt = 0x0,
fn_expr= 0x0}, sk_argument = 0}, {sk_flags = 1296236544, sk_attno = 0, sk_strategy = 0, sk_subtype = 3879362536,
sk_collation= 22006, sk_func = {fn_addr = 0x1, fn_oid = 0, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats
=0 '\000', fn_extra = 0x0, fn_mcxt = 0x7ffc0d14c0c0, fn_expr = 0x0}, sk_argument = 0}, {sk_flags = -415604760, sk_attno
=22006, sk_strategy = 0, sk_subtype = 219463536, sk_collation = 32764, sk_func = {fn_addr = 0x55f6e5779cb6
<AllocSetAlloc+2370>,fn_oid = 40, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 32 ' ', fn_extra =
0x0,fn_mcxt = 0x2000000000064, fn_expr = 0x4eb}, sk_argument = 1259}, {sk_flags = 1259, sk_attno = 0, sk_strategy = 0,
sk_subtype= 219463056, sk_collation = 32764, sk_func = {fn_addr = 0x337dafc200000028, fn_oid = 1259, fn_nargs = 1259,
fn_strict= false, fn_retset = false, fn_stats = 64 '@', fn_extra = 0x55f6e5752d7a <FunctionCall2Coll+160>, fn_mcxt =
0x4eb,fn_expr = 0x4eb}, sk_argument = 429496729600}, {sk_flags = -414987040, sk_attno = 22006, sk_strategy = 0,
sk_subtype= 3879980256, sk_collation = 22006, sk_func = {fn_addr = 0x0, fn_oid = 0, fn_nargs = 0, fn_strict = false,
fn_retset= false, fn_stats = 100 'd', fn_extra = 0x4eb, fn_mcxt = 0x80, fn_expr = 0xd14cb70}, sk_argument =
17179869199},{sk_flags = 219463744, sk_attno = 32764, sk_strategy = 0, sk_subtype = 3849819694, sk_collation = 22006,
sk_func= {fn_addr = 0x80, fn_oid = 3879978352, fn_nargs = 22006, fn_strict = false, fn_retset = false, fn_stats = 48
'0',fn_extra = 0x7f0de4ed1700, fn_mcxt = 0x7ffc0d14be30, fn_expr = 0x1c6e55c6297}, sk_argument = 140720527949472},
{sk_flags= -445281983, sk_attno = 22006, sk_strategy = 0, sk_subtype = 0, sk_collation = 0, sk_func = {fn_addr =
0xad8dc1c600000000,fn_oid = 219463488, fn_nargs = 32764, fn_strict = false, fn_retset = false, fn_stats = 248 '\370',
fn_extra= 0x4d430001, fn_mcxt = 0x55f6e73a5fa8, fn_expr = 0x18}, sk_argument = 0}, {sk_flags = 0, sk_attno = 0,
sk_strategy= 0, sk_subtype = 0, sk_collation = 0, sk_func = {fn_addr = 0x4d430000, fn_oid = 3879362536, fn_nargs =
22006,fn_strict = false, fn_retset = false, fn_stats = 24 '\030', fn_extra = 0x0, fn_mcxt = 0x0, fn_expr = 0x0},
sk_argument= 1296236544}, {sk_flags = -415604824, sk_attno = 22006, sk_strategy = 0, sk_subtype = 16, sk_collation = 0,
sk_func= {fn_addr = 0x0, fn_oid = 0, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 0 '\000', fn_extra
=0x7ffc0d14bf10, fn_mcxt = 0x0, fn_expr = 0x0}, sk_argument = 0}, {sk_flags = 219463904, sk_attno = 32764, sk_strategy
=0, sk_subtype = 0, sk_collation = 0, sk_func = {fn_addr = 0x7ffc0d14c170, fn_oid = 3849819694, fn_nargs = 22006,
fn_strict= false, fn_retset = false, fn_stats = 8 '\b', fn_extra = 0x55f6e73a12b0, fn_mcxt = 0x55f6e743ceb8, fn_expr =
0x3e743ceb8},sk_argument = 94518929678248}, {sk_flags = 64, sk_attno = 0, sk_strategy = 0, sk_subtype = 3879195424,
sk_collation= 22006, sk_func = {fn_addr = 0x55f6e743ceb8, fn_oid = 3879980855, fn_nargs = 22006, fn_strict = false,
fn_retset= false, fn_stats = 104 'h', fn_extra = 0x0, fn_mcxt = 0x55f6e73a5b10, fn_expr = 0x7ffc0d14bff0}, sk_argument
=94518900186290}, {sk_flags = 1296236544, sk_attno = 0, sk_strategy = 0, sk_subtype = 40, sk_collation = 0, sk_func =
{fn_addr= 0x1305, fn_oid = 3879195424, fn_nargs = 22006, fn_strict = false, fn_retset = false, fn_stats = 192 '\300',
fn_extra= 0x28, fn_mcxt = 0x0, fn_expr = 0x0}, sk_argument = 128}, {sk_flags = 0, sk_attno = 0, sk_strategy = 0,
sk_subtype= 3879362496, sk_collation = 22006, sk_func = {fn_addr = 0x55f6e737d320, fn_oid = 0, fn_nargs = 0, fn_strict
=false, fn_retset = false, fn_stats = 0 '\000', fn_extra = 0x7ffc0d14c350, fn_mcxt = 0x55f6e545a384
<expression_tree_mutator+222>,fn_expr = 0x55f6e743cea0}, sk_argument = 140720527958992}, {sk_flags = -447769879,
sk_attno= 22006, sk_strategy = 0, sk_subtype = 3879202312, sk_collation = 22006, sk_func = {fn_addr = 0x8, fn_oid =
5840,fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 0 '\000', fn_extra = 0x55f6e73b07a0, fn_mcxt = 0x0,
fn_expr= 0x0}, sk_argument = 0}, {sk_flags = 0, sk_attno = 0, sk_strategy = 0, sk_subtype = 1296236544, sk_collation =
0,sk_func = {fn_addr = 0x55f6e73b0708, fn_oid = 16, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 0
'\000',fn_extra = 0x0, fn_mcxt = 0x7ffc0d14c0d0, fn_expr = 0x80}, sk_argument = 720304670261248}, {sk_flags =
219464832,sk_attno = 32764, sk_strategy = 0, sk_subtype = 3849661818, sk_collation = 22006, sk_func = {fn_addr =
0x4000,fn_oid = 167709, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 0 '\000', fn_extra =
0x7ffc0d14cf30,fn_mcxt = 0x7ffc0d14cf30, fn_expr = 0x0}, sk_argument = 0}, {sk_flags = 0, sk_attno = 0, sk_strategy =
2,sk_subtype = 167709, sk_collation = 0, sk_func = {fn_addr = 0x4000, fn_oid = 167709, fn_nargs = 0, fn_strict = false,
fn_retset= false, fn_stats = 80 'P', fn_extra = 0x0, fn_mcxt = 0x400200004000, fn_expr = 0x7ffc0d14c500}, sk_argument =
94518899977594},{sk_flags = 16384, sk_attno = 0, sk_strategy = 0, sk_subtype = 16386, sk_collation = 0, sk_func =
{fn_addr= 0xe73a12b0, fn_oid = 3879979168, fn_nargs = 22006, fn_strict = false, fn_retset = false, fn_stats = 160
'\240',fn_extra = 0x0, fn_mcxt = 0x0, fn_expr = 0x2000000000000}, sk_argument = 16386}, {sk_flags = 16384, sk_attno =
0,sk_strategy = 0, sk_subtype = 219467568, sk_collation = 32764, sk_func = {fn_addr = 0x0, fn_oid = 0, fn_nargs = 0,
fn_strict= false, fn_retset = false, fn_stats = 0 '\000', fn_extra = 0x305c, fn_mcxt = 0x4000, fn_expr =
0x69c55c360d14c1d0},sk_argument = 139697652045568}, {sk_flags = 219464160, sk_attno = 1, sk_strategy = 0, sk_subtype =
3822594436,sk_collation = 3126, sk_func = {fn_addr = 0x7ffc0d14c260, fn_oid = 3849685313, fn_nargs = 22006, fn_strict =
false,fn_retset = false, fn_stats = 0 '\000', fn_extra = 0x69c55c3600000000, fn_mcxt = 0x7ffc0d14c300, fn_expr =
0x83140001e73780f8},sk_argument = 140720527950452}, {sk_flags = -471124968, sk_attno = 32525, sk_strategy = 0,
sk_subtype= 1781, sk_collation = 1, sk_func = {fn_addr = 0x7f0de3d83d84, fn_oid = 219464256, fn_nargs = 32764,
fn_strict= false, fn_retset = false, fn_stats = 156 '\234', fn_extra = 0x10d14c250, fn_mcxt = 0x7f0de3d83d84, fn_expr =
0x7ffc0d14c260},sk_argument = 94518898344476}, {sk_flags = 219464336, sk_attno = 1, sk_strategy = 0, sk_subtype =
3822599556,sk_collation = 32525, sk_func = {fn_addr = 0x7ffc0d14c290, fn_oid = 3848037015, fn_nargs = 22006, fn_strict
=false, fn_retset = false, fn_stats = 144 '\220', fn_extra = 0x7f0de3d83d80, fn_mcxt = 0x1, fn_expr =
0x2000000000ee9c10},sk_argument = 140720527950688}, {sk_flags = -447135523, sk_attno = 22006, sk_strategy = 0,
sk_subtype= 3, sk_collation = 0, sk_func = {fn_addr = 0x7ffc0d14c3b3, fn_oid = 0, fn_nargs = 0, fn_strict = false,
fn_retset= false, fn_stats = 16 '\020', fn_extra = 0x7f7000000000, fn_mcxt = 0x55f6e7415de0, fn_expr = 0x7f0de3d82980},
sk_argument= 8204046756560287030}} 
        keysCount = 1
        i = 1
        status = true
        strat_total = 3
        currItem = 0x0
        blkno = 2198601728
        __func__ = "_bt_first"
#12 0x000055f6e520ea2a in btgettuple (scan=0x55f6e743c6b0, dir=ForwardScanDirection) at
/home/andres/src/postgresql/src/backend/access/nbtree/nbtree.c:245
        so = 0x55f6e74405d0
        res = false
#13 0x000055f6e5201a6a in index_getnext_tid (scan=0x55f6e743c6b0, direction=ForwardScanDirection) at
/home/andres/src/postgresql/src/backend/access/index/indexam.c:541
        found = false
        __func__ = "index_getnext_tid"
#14 0x000055f6e5201ee1 in index_getnext (scan=0x55f6e743c6b0, direction=ForwardScanDirection) at
/home/andres/src/postgresql/src/backend/access/index/indexam.c:679
        heapTuple = 0x55f6e5aadec0 <CatalogSnapshotData+64>
        tid = 0x7ffc0d14ce60
#15 0x000055f6e5200347 in systable_getnext (sysscan=0x55f6e743c7c8) at
/home/andres/src/postgresql/src/backend/access/index/genam.c:411
        htup = 0x7f0de627a850
        __func__ = "systable_getnext"
#16 0x000055f6e5733253 in ScanPgRelation (targetRelId=1259, indexOK=true, force_non_historic=false) at
/home/andres/src/postgresql/src/backend/utils/cache/relcache.c:358
        pg_class_tuple = 0x55f6e5aae2c0 <TopTransactionStateData>
        pg_class_desc = 0x7f0de3d472b0
        pg_class_scan = 0x55f6e743c7c8
        key = {{sk_flags = 0, sk_attno = 1, sk_strategy = 3, sk_subtype = 0, sk_collation = 100, sk_func = {fn_addr =
0x55f6e569cbf8<oideq>, fn_oid = 184, fn_nargs = 2, fn_strict = true, fn_retset = false, fn_stats = 2 '\002', fn_extra =
0x0,fn_mcxt = 0x55f6e743c570, fn_expr = 0x0}, sk_argument = 1259}} 
        snapshot = 0x55f6e5aade80 <CatalogSnapshotData>
        __func__ = "ScanPgRelation"
#17 0x000055f6e5736fd0 in RelationReloadNailed (relation=0x7f0de3d472b0) at
/home/andres/src/postgresql/src/backend/utils/cache/relcache.c:2208
        pg_class_tuple = 0x4e73b0540
        relp = 0x7f0de3d472c0
#18 0x000055f6e5737414 in RelationClearRelation (relation=0x7f0de3d472b0, rebuild=true) at
/home/andres/src/postgresql/src/backend/utils/cache/relcache.c:2343
        __func__ = "RelationClearRelation"
#19 0x000055f6e5737aaf in RelationFlushRelation (relation=0x7f0de3d472b0) at
/home/andres/src/postgresql/src/backend/utils/cache/relcache.c:2584
        rebuild = true
#20 0x000055f6e5737bc8 in RelationCacheInvalidateEntry (relationId=1259) at
/home/andres/src/postgresql/src/backend/utils/cache/relcache.c:2636
        relation = 0x7f0de3d472b0
#21 0x000055f6e5728fe4 in LocalExecuteInvalidationMessage (msg=0x7ffc0d14d220) at
/home/andres/src/postgresql/src/backend/utils/cache/inval.c:587
        i = 20
        __func__ = "LocalExecuteInvalidationMessage"
#22 0x000055f6e55b27c0 in ReceiveSharedInvalidMessages (invalFunction=0x55f6e5728edd <LocalExecuteInvalidationMessage>,
resetFunction=0x55f6e5729149<InvalidateSystemCaches>) at
/home/andres/src/postgresql/src/backend/storage/ipc/sinval.c:121
        msg = {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 1259}, cat = {id = -2 '\376', dbId =
12397,catId = 1259}, rc = {id = -2 '\376', dbId = 12397, relId = 1259}, sm = {id = -2 '\376', backend_hi = -114 '\216',
backend_lo= 58738, rnode = {spcNode = 12397, dbNode = 1259, relNode = 22006}}, rm = {id = -2 '\376', dbId = 12397}, sn
={id = -2 '\376', dbId = 12397, relId = 1259}} 
        getResult = 20
        messages = {{id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 1259}, cat = {id = -2 '\376', dbId
=12397, catId = 1259}, rc = {id = -2 '\376', dbId = 12397, relId = 1259}, sm = {id = -2 '\376', backend_hi = -114
'\216',backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 1259, relNode = 22006}}, rm = {id = -2 '\376', dbId =
12397},sn = {id = -2 '\376', dbId = 12397, relId = 1259}}, {id = -5 '\373', cc = {id = -5 '\373', dbId = 12397,
hashValue= 2608}, cat = {id = -5 '\373', dbId = 12397, catId = 2608}, rc = {id = -5 '\373', dbId = 12397, relId =
2608},sm = {id = -5 '\373', backend_hi = -37 '\333', backend_lo = 3348, rnode = {spcNode = 12397, dbNode = 2608,
relNode= 11}}, rm = {id = -5 '\373', dbId = 12397}, sn = {id = -5 '\373', dbId = 12397, relId = 2608}}, {id = -2
'\376',cc = {id = -2 '\376', dbId = 12397, hashValue = 1259}, cat = {id = -2 '\376', dbId = 12397, catId = 1259}, rc =
{id= -2 '\376', dbId = 12397, relId = 1259}, sm = {id = -2 '\376', backend_hi = -38 '\332', backend_lo = 3348, rnode =
{spcNode= 12397, dbNode = 1259, relNode = 22006}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId =
12397,relId = 1259}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 3455}, cat = {id = -2 '\376',
dbId= 12397, catId = 3455}, rc = {id = -2 '\376', dbId = 12397, relId = 3455}, sm = {id = -2 '\376', backend_hi = -114
'\216',backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 3455, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397},
sn= {id = -2 '\376', dbId = 12397, relId = 3455}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue =
3455},cat = {id = -2 '\376', dbId = 12397, catId = 3455}, rc = {id = -2 '\376', dbId = 12397, relId = 3455}, sm = {id =
-2'\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 3455, relNode = 22006}}, rm
={id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 3455}}, {id = -2 '\376', cc = {id = -2
'\376',dbId = 12397, hashValue = 1259}, cat = {id = -2 '\376', dbId = 12397, catId = 1259}, rc = {id = -2 '\376', dbId
=12397, relId = 1259}, sm = {id = -2 '\376', backend_hi = -38 '\332', backend_lo = 3348, rnode = {spcNode = 12397,
dbNode= 1259, relNode = 22006}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId =
1259}},{id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 2663}, cat = {id = -2 '\376', dbId = 12397,
catId= 2663}, rc = {id = -2 '\376', dbId = 12397, relId = 2663}, sm = {id = -2 '\376', backend_hi = -114 '\216',
backend_lo= 58738, rnode = {spcNode = 12397, dbNode = 2663, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn =
{id= -2 '\376', dbId = 12397, relId = 2663}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 2663},
cat= {id = -2 '\376', dbId = 12397, catId = 2663}, rc = {id = -2 '\376', dbId = 12397, relId = 2663}, sm = {id = -2
'\376',backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 2663, relNode = 22006}}, rm =
{id= -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 2663}}, {id = -2 '\376', cc = {id = -2
'\376',dbId = 12397, hashValue = 1259}, cat = {id = -2 '\376', dbId = 12397, catId = 1259}, rc = {id = -2 '\376', dbId
=12397, relId = 1259}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397,
dbNode= 1259, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 1259}},
{id= -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 2662}, cat = {id = -2 '\376', dbId = 12397, catId =
2662},rc = {id = -2 '\376', dbId = 12397, relId = 2662}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo =
58738,rnode = {spcNode = 12397, dbNode = 2662, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2
'\376',dbId = 12397, relId = 2662}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 2662}, cat = {id
=-2 '\376', dbId = 12397, catId = 2662}, rc = {id = -2 '\376', dbId = 12397, relId = 2662}, sm = {id = -2 '\376',
backend_hi= -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 2662, relNode = 22006}}, rm = {id = -2
'\376',dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 2662}}, {id = -2 '\376', cc = {id = -2 '\376', dbId =
12397,hashValue = 1259}, cat = {id = -2 '\376', dbId = 12397, catId = 1259}, rc = {id = -2 '\376', dbId = 12397, relId
=1259}, sm = {id = -2 '\376', backend_hi = 0 '\000', backend_lo = 0, rnode = {spcNode = 12397, dbNode = 1259, relNode =
32525}},rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 1259}}, {id = -2 '\376', cc =
{id= -2 '\376', dbId = 12397, hashValue = 167949}, cat = {id = -2 '\376', dbId = 12397, catId = 167949}, rc = {id = -2
'\376',dbId = 12397, relId = 167949}, sm = {id = -2 '\376', backend_hi = 0 '\000', backend_lo = 0, rnode = {spcNode =
12397,dbNode = 167949, relNode = 11}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId =
167949}},{id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 167949}, cat = {id = -2 '\376', dbId = 12397,
catId= 167949}, rc = {id = -2 '\376', dbId = 12397, relId = 167949}, sm = {id = -2 '\376', backend_hi = 0 '\000',
backend_lo= 0, rnode = {spcNode = 12397, dbNode = 167949, relNode = 32525}}, rm = {id = -2 '\376', dbId = 12397}, sn =
{id= -2 '\376', dbId = 12397, relId = 167949}}, {id = -5 '\373', cc = {id = -5 '\373', dbId = 12397, hashValue = 2608},
cat= {id = -5 '\373', dbId = 12397, catId = 2608}, rc = {id = -5 '\373', dbId = 12397, relId = 2608}, sm = {id = -5
'\373',backend_hi = -41 '\327', backend_lo = 3348, rnode = {spcNode = 12397, dbNode = 2608, relNode = 11}}, rm = {id =
-5'\373', dbId = 12397}, sn = {id = -5 '\373', dbId = 12397, relId = 2608}}, {id = -2 '\376', cc = {id = -2 '\376',
dbId= 12397, hashValue = 167949}, cat = {id = -2 '\376', dbId = 12397, catId = 167949}, rc = {id = -2 '\376', dbId =
12397,relId = 167949}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397,
dbNode= 167949, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId =
167949}},{id = -3 '\375', cc = {id = -3 '\375', dbId = 1663, hashValue = 12397}, cat = {id = -3 '\375', dbId = 1663,
catId= 12397}, rc = {id = -3 '\375', dbId = 1663, relId = 12397}, sm = {id = -3 '\375', backend_hi = -1 '\377',
backend_lo= 65535, rnode = {spcNode = 1663, dbNode = 12397, relNode = 167943}}, rm = {id = -3 '\375', dbId = 1663}, sn
={id = -3 '\375', dbId = 1663, relId = 12397}}, {id = -3 '\375', cc = {id = -3 '\375', dbId = 1663, hashValue = 12397},
cat= {id = -3 '\375', dbId = 1663, catId = 12397}, rc = {id = -3 '\375', dbId = 1663, relId = 12397}, sm = {id = -3
'\375',backend_hi = -1 '\377', backend_lo = 65535, rnode = {spcNode = 1663, dbNode = 12397, relNode = 167948}}, rm =
{id= -3 '\375', dbId = 1663}, sn = {id = -3 '\375', dbId = 1663, relId = 12397}}, {id = -3 '\375', cc = {id = -3
'\375',dbId = 1663, hashValue = 12397}, cat = {id = -3 '\375', dbId = 1663, catId = 12397}, rc = {id = -3 '\375', dbId
=1663, relId = 12397}, sm = {id = -3 '\375', backend_hi = -1 '\377', backend_lo = 65535, rnode = {spcNode = 1663,
dbNode= 12397, relNode = 167947}}, rm = {id = -3 '\375', dbId = 1663}, sn = {id = -3 '\375', dbId = 1663, relId =
12397}},{id = -3 '\375', cc = {id = -3 '\375', dbId = 1663, hashValue = 12397}, cat = {id = -3 '\375', dbId = 1663,
catId= 12397}, rc = {id = -3 '\375', dbId = 1663, relId = 12397}, sm = {id = -3 '\375', backend_hi = -1 '\377',
backend_lo= 65535, rnode = {spcNode = 1663, dbNode = 12397, relNode = 167946}}, rm = {id = -3 '\375', dbId = 1663}, sn
={id = -3 '\375', dbId = 1663, relId = 12397}}, {id = 7 '\a', cc = {id = 7 '\a', dbId = 12397, hashValue = 1528188348},
cat= {id = 7 '\a', dbId = 12397, catId = 1528188348}, rc = {id = 7 '\a', dbId = 12397, relId = 1528188348}, sm = {id =
7'\a', backend_hi = -10 '\366', backend_lo = 58325, rnode = {spcNode = 12397, dbNode = 1528188348, relNode = 22006}},
rm= {id = 7 '\a', dbId = 12397}, sn = {id = 7 '\a', dbId = 12397, relId = 1528188348}}, {id = 6 '\006', cc = {id = 6
'\006',dbId = 12397, hashValue = 2483940397}, cat = {id = 6 '\006', dbId = 12397, catId = 2483940397}, rc = {id = 6
'\006',dbId = 12397, relId = 2483940397}, sm = {id = 6 '\006', backend_hi = 7 '\a', backend_lo = 58326, rnode =
{spcNode= 12397, dbNode = 2483940397, relNode = 22006}}, rm = {id = 6 '\006', dbId = 12397}, sn = {id = 6 '\006', dbId
=12397, relId = 2483940397}}, {id = 7 '\a', cc = {id = 7 '\a', dbId = 12397, hashValue = 37473943}, cat = {id = 7 '\a',
dbId= 12397, catId = 37473943}, rc = {id = 7 '\a', dbId = 12397, relId = 37473943}, sm = {id = 7 '\a', backend_hi = -10
'\366',backend_lo = 58325, rnode = {spcNode = 12397, dbNode = 37473943, relNode = 22006}}, rm = {id = 7 '\a', dbId =
12397},sn = {id = 7 '\a', dbId = 12397, relId = 37473943}}, {id = 6 '\006', cc = {id = 6 '\006', dbId = 12397,
hashValue= 2828489776}, cat = {id = 6 '\006', dbId = 12397, catId = 2828489776}, rc = {id = 6 '\006', dbId = 12397,
relId= 2828489776}, sm = {id = 6 '\006', backend_hi = 7 '\a', backend_lo = 58326, rnode = {spcNode = 12397, dbNode =
2828489776,relNode = 22006}}, rm = {id = 6 '\006', dbId = 12397}, sn = {id = 6 '\006', dbId = 12397, relId =
2828489776}},{id = 7 '\a', cc = {id = 7 '\a', dbId = 12397, hashValue = 2277595885}, cat = {id = 7 '\a', dbId = 12397,
catId= 2277595885}, rc = {id = 7 '\a', dbId = 12397, relId = 2277595885}, sm = {id = 7 '\a', backend_hi = -10 '\366',
backend_lo= 58325, rnode = {spcNode = 12397, dbNode = 2277595885, relNode = 22006}}, rm = {id = 7 '\a', dbId = 12397},
sn= {id = 7 '\a', dbId = 12397, relId = 2277595885}}, {id = 6 '\006', cc = {id = 6 '\006', dbId = 12397, hashValue =
3442084044},cat = {id = 6 '\006', dbId = 12397, catId = 3442084044}, rc = {id = 6 '\006', dbId = 12397, relId =
3442084044},sm = {id = 6 '\006', backend_hi = 7 '\a', backend_lo = 58326, rnode = {spcNode = 12397, dbNode =
3442084044,relNode = 22006}}, rm = {id = 6 '\006', dbId = 12397}, sn = {id = 6 '\006', dbId = 12397, relId =
3442084044}},{id = 7 '\a', cc = {id = 7 '\a', dbId = 12397, hashValue = 2945592578}, cat = {id = 7 '\a', dbId = 12397,
catId= 2945592578}, rc = {id = 7 '\a', dbId = 12397, relId = 2945592578}, sm = {id = 7 '\a', backend_hi = -10 '\366',
backend_lo= 58325, rnode = {spcNode = 12397, dbNode = 2945592578, relNode = 22006}}, rm = {id = 7 '\a', dbId = 12397},
sn= {id = 7 '\a', dbId = 12397, relId = 2945592578}}, {id = 6 '\006', cc = {id = 6 '\006', dbId = 12397, hashValue =
134785355},cat = {id = 6 '\006', dbId = 12397, catId = 134785355}, rc = {id = 6 '\006', dbId = 12397, relId =
134785355},sm = {id = 6 '\006', backend_hi = 7 '\a', backend_lo = 58326, rnode = {spcNode = 12397, dbNode = 134785355,
relNode= 22006}}, rm = {id = 6 '\006', dbId = 12397}, sn = {id = 6 '\006', dbId = 12397, relId = 134785355}}, {id = 7
'\a',cc = {id = 7 '\a', dbId = 12397, hashValue = 2621623531}, cat = {id = 7 '\a', dbId = 12397, catId = 2621623531},
rc= {id = 7 '\a', dbId = 12397, relId = 2621623531}, sm = {id = 7 '\a', backend_hi = -10 '\366', backend_lo = 58325,
rnode= {spcNode = 12397, dbNode = 2621623531, relNode = 22006}}, rm = {id = 7 '\a', dbId = 12397}, sn = {id = 7 '\a',
dbId= 12397, relId = 2621623531}}, {id = 6 '\006', cc = {id = 6 '\006', dbId = 12397, hashValue = 3549520513}, cat =
{id= 6 '\006', dbId = 12397, catId = 3549520513}, rc = {id = 6 '\006', dbId = 12397, relId = 3549520513}, sm = {id = 6
'\006',backend_hi = 7 '\a', backend_lo = 58326, rnode = {spcNode = 12397, dbNode = 3549520513, relNode = 22006}}, rm =
{id= 6 '\006', dbId = 12397}, sn = {id = 6 '\006', dbId = 12397, relId = 3549520513}}, {id = -2 '\376', cc = {id = -2
'\376',dbId = 12397, hashValue = 167949}, cat = {id = -2 '\376', dbId = 12397, catId = 167949}, rc = {id = -2 '\376',
dbId= 12397, relId = 167949}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode =
12397,dbNode = 167949, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId =
167949}},{id = -5 '\373', cc = {id = -5 '\373', dbId = 12397, hashValue = 2608}, cat = {id = -5 '\373', dbId = 12397,
catId= 2608}, rc = {id = -5 '\373', dbId = 12397, relId = 2608}, sm = {id = -5 '\373', backend_hi = -37 '\333',
backend_lo= 3348, rnode = {spcNode = 12397, dbNode = 2608, relNode = 11}}, rm = {id = -5 '\373', dbId = 12397}, sn =
{id= -5 '\373', dbId = 12397, relId = 2608}}} 
        nextmsg = 1
        nummsgs = 20
        __func__ = "ReceiveSharedInvalidMessages"
#23 0x000055f6e5729223 in AcceptInvalidationMessages () at
/home/andres/src/postgresql/src/backend/utils/cache/inval.c:681
No locals.
#24 0x000055f6e55b6825 in LockRelationOid (relid=2662, lockmode=1) at
/home/andres/src/postgresql/src/backend/storage/lmgr/lmgr.c:125
        tag = {locktag_field1 = 12397, locktag_field2 = 2662, locktag_field3 = 0, locktag_field4 = 0, locktag_type = 0
'\000',locktag_lockmethodid = 1 '\001'} 
        res = LOCKACQUIRE_OK
#25 0x000055f6e51e11f8 in relation_open (relationId=2662, lockmode=1) at
/home/andres/src/postgresql/src/backend/access/heap/heapam.c:1132
        r = 0x55f6e545f1f6 <list_member_oid+90>
        __func__ = "relation_open"
#26 0x000055f6e5200a77 in index_open (relationId=2662, lockmode=1) at
/home/andres/src/postgresql/src/backend/access/index/indexam.c:154
        r = 0x55f6e528787f <ReindexIsProcessingIndex+42>
        __func__ = "index_open"
#27 0x000055f6e5200111 in systable_beginscan (heapRelation=0x7f0de3d472b0, indexId=2662, indexOK=true,
snapshot=0x55f6e5aade80<CatalogSnapshotData>, nkeys=1, key=0x7ffc0d14d390) at
/home/andres/src/postgresql/src/backend/access/index/genam.c:329
        sysscan = 0x55f6e57a285f <GetCatalogSnapshot+39>
        irel = 0x4eb00000000
        __func__ = "systable_beginscan"
#28 0x000055f6e5733243 in ScanPgRelation (targetRelId=16390, indexOK=true, force_non_historic=false) at
/home/andres/src/postgresql/src/backend/utils/cache/relcache.c:353
        pg_class_tuple = 0x55f6e73a8340
        pg_class_desc = 0x7f0de3d472b0
        pg_class_scan = 0x0
        key = {{sk_flags = 0, sk_attno = -2, sk_strategy = 3, sk_subtype = 0, sk_collation = 100, sk_func = {fn_addr =
0x55f6e569cbf8<oideq>, fn_oid = 184, fn_nargs = 2, fn_strict = true, fn_retset = false, fn_stats = 2 '\002', fn_extra =
0x0,fn_mcxt = 0x55f6e743c570, fn_expr = 0x0}, sk_argument = 16390}} 
        snapshot = 0x55f6e5aade80 <CatalogSnapshotData>
        __func__ = "ScanPgRelation"
#29 0x000055f6e5736c9c in RelationReloadIndexInfo (relation=0x7f0de3d5c020) at
/home/andres/src/postgresql/src/backend/utils/cache/relcache.c:2086
        indexOK = true
        pg_class_tuple = 0x7f0de3d5c030
        relp = 0x55f6e74152f0
        __func__ = "RelationReloadIndexInfo"
#30 0x000055f6e5737487 in RelationClearRelation (relation=0x7f0de3d5c020, rebuild=true) at
/home/andres/src/postgresql/src/backend/utils/cache/relcache.c:2361
        __func__ = "RelationClearRelation"
#31 0x000055f6e5737aaf in RelationFlushRelation (relation=0x7f0de3d5c020) at
/home/andres/src/postgresql/src/backend/utils/cache/relcache.c:2584
        rebuild = true
#32 0x000055f6e5737bc8 in RelationCacheInvalidateEntry (relationId=16390) at
/home/andres/src/postgresql/src/backend/utils/cache/relcache.c:2636
        relation = 0x7f0de3d5c020
#33 0x000055f6e5728fe4 in LocalExecuteInvalidationMessage (msg=0x7ffc0d14d780) at
/home/andres/src/postgresql/src/backend/utils/cache/inval.c:587
        i = 22006
        __func__ = "LocalExecuteInvalidationMessage"
#34 0x000055f6e55b26d6 in ReceiveSharedInvalidMessages (invalFunction=0x55f6e5728edd <LocalExecuteInvalidationMessage>,
resetFunction=0x55f6e5729149<InvalidateSystemCaches>) at
/home/andres/src/postgresql/src/backend/storage/ipc/sinval.c:91
        msg = {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 16390}, cat = {id = -2 '\376', dbId =
12397,catId = 16390}, rc = {id = -2 '\376', dbId = 12397, relId = 16390}, sm = {id = -2 '\376', backend_hi = -114
'\216',backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 16390, relNode = 0}}, rm = {id = -2 '\376', dbId =
12397},sn = {id = -2 '\376', dbId = 12397, relId = 16390}} 
        messages = {{id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 1259}, cat = {id = -2 '\376', dbId
=12397, catId = 1259}, rc = {id = -2 '\376', dbId = 12397, relId = 1259}, sm = {id = -2 '\376', backend_hi = -114
'\216',backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 1259, relNode = 22006}}, rm = {id = -2 '\376', dbId =
12397},sn = {id = -2 '\376', dbId = 12397, relId = 1259}}, {id = -5 '\373', cc = {id = -5 '\373', dbId = 12397,
hashValue= 2608}, cat = {id = -5 '\373', dbId = 12397, catId = 2608}, rc = {id = -5 '\373', dbId = 12397, relId =
2608},sm = {id = -5 '\373', backend_hi = -37 '\333', backend_lo = 3348, rnode = {spcNode = 12397, dbNode = 2608,
relNode= 11}}, rm = {id = -5 '\373', dbId = 12397}, sn = {id = -5 '\373', dbId = 12397, relId = 2608}}, {id = -2
'\376',cc = {id = -2 '\376', dbId = 12397, hashValue = 1259}, cat = {id = -2 '\376', dbId = 12397, catId = 1259}, rc =
{id= -2 '\376', dbId = 12397, relId = 1259}, sm = {id = -2 '\376', backend_hi = -38 '\332', backend_lo = 3348, rnode =
{spcNode= 12397, dbNode = 1259, relNode = 22006}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId =
12397,relId = 1259}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 3455}, cat = {id = -2 '\376',
dbId= 12397, catId = 3455}, rc = {id = -2 '\376', dbId = 12397, relId = 3455}, sm = {id = -2 '\376', backend_hi = -114
'\216',backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 3455, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397},
sn= {id = -2 '\376', dbId = 12397, relId = 3455}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue =
3455},cat = {id = -2 '\376', dbId = 12397, catId = 3455}, rc = {id = -2 '\376', dbId = 12397, relId = 3455}, sm = {id =
-2'\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 3455, relNode = 22006}}, rm
={id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 3455}}, {id = -2 '\376', cc = {id = -2
'\376',dbId = 12397, hashValue = 1259}, cat = {id = -2 '\376', dbId = 12397, catId = 1259}, rc = {id = -2 '\376', dbId
=12397, relId = 1259}, sm = {id = -2 '\376', backend_hi = -38 '\332', backend_lo = 3348, rnode = {spcNode = 12397,
dbNode= 1259, relNode = 22006}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId =
1259}},{id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 2663}, cat = {id = -2 '\376', dbId = 12397,
catId= 2663}, rc = {id = -2 '\376', dbId = 12397, relId = 2663}, sm = {id = -2 '\376', backend_hi = -114 '\216',
backend_lo= 58738, rnode = {spcNode = 12397, dbNode = 2663, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn =
{id= -2 '\376', dbId = 12397, relId = 2663}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 2663},
cat= {id = -2 '\376', dbId = 12397, catId = 2663}, rc = {id = -2 '\376', dbId = 12397, relId = 2663}, sm = {id = -2
'\376',backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 2663, relNode = 22006}}, rm =
{id= -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 2663}}, {id = -2 '\376', cc = {id = -2
'\376',dbId = 12397, hashValue = 1259}, cat = {id = -2 '\376', dbId = 12397, catId = 1259}, rc = {id = -2 '\376', dbId
=12397, relId = 1259}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397,
dbNode= 1259, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 1259}},
{id= -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 2662}, cat = {id = -2 '\376', dbId = 12397, catId =
2662},rc = {id = -2 '\376', dbId = 12397, relId = 2662}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo =
58738,rnode = {spcNode = 12397, dbNode = 2662, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2
'\376',dbId = 12397, relId = 2662}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 2662}, cat = {id
=-2 '\376', dbId = 12397, catId = 2662}, rc = {id = -2 '\376', dbId = 12397, relId = 2662}, sm = {id = -2 '\376',
backend_hi= -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 2662, relNode = 22006}}, rm = {id = -2
'\376',dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 2662}}, {id = -2 '\376', cc = {id = -2 '\376', dbId =
12397,hashValue = 1259}, cat = {id = -2 '\376', dbId = 12397, catId = 1259}, rc = {id = -2 '\376', dbId = 12397, relId
=1259}, sm = {id = -2 '\376', backend_hi = 0 '\000', backend_lo = 0, rnode = {spcNode = 12397, dbNode = 1259, relNode =
32525}},rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 1259}}, {id = -2 '\376', cc =
{id= -2 '\376', dbId = 12397, hashValue = 167949}, cat = {id = -2 '\376', dbId = 12397, catId = 167949}, rc = {id = -2
'\376',dbId = 12397, relId = 167949}, sm = {id = -2 '\376', backend_hi = 0 '\000', backend_lo = 0, rnode = {spcNode =
12397,dbNode = 167949, relNode = 11}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId =
167949}},{id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 167949}, cat = {id = -2 '\376', dbId = 12397,
catId= 167949}, rc = {id = -2 '\376', dbId = 12397, relId = 167949}, sm = {id = -2 '\376', backend_hi = 0 '\000',
backend_lo= 0, rnode = {spcNode = 12397, dbNode = 167949, relNode = 32525}}, rm = {id = -2 '\376', dbId = 12397}, sn =
{id= -2 '\376', dbId = 12397, relId = 167949}}, {id = -5 '\373', cc = {id = -5 '\373', dbId = 12397, hashValue = 2608},
cat= {id = -5 '\373', dbId = 12397, catId = 2608}, rc = {id = -5 '\373', dbId = 12397, relId = 2608}, sm = {id = -5
'\373',backend_hi = -41 '\327', backend_lo = 3348, rnode = {spcNode = 12397, dbNode = 2608, relNode = 11}}, rm = {id =
-5'\373', dbId = 12397}, sn = {id = -5 '\373', dbId = 12397, relId = 2608}}, {id = -2 '\376', cc = {id = -2 '\376',
dbId= 12397, hashValue = 167949}, cat = {id = -2 '\376', dbId = 12397, catId = 167949}, rc = {id = -2 '\376', dbId =
12397,relId = 167949}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397,
dbNode= 167949, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId =
167949}},{id = -3 '\375', cc = {id = -3 '\375', dbId = 1663, hashValue = 12397}, cat = {id = -3 '\375', dbId = 1663,
catId= 12397}, rc = {id = -3 '\375', dbId = 1663, relId = 12397}, sm = {id = -3 '\375', backend_hi = -1 '\377',
backend_lo= 65535, rnode = {spcNode = 1663, dbNode = 12397, relNode = 167943}}, rm = {id = -3 '\375', dbId = 1663}, sn
={id = -3 '\375', dbId = 1663, relId = 12397}}, {id = -3 '\375', cc = {id = -3 '\375', dbId = 1663, hashValue = 12397},
cat= {id = -3 '\375', dbId = 1663, catId = 12397}, rc = {id = -3 '\375', dbId = 1663, relId = 12397}, sm = {id = -3
'\375',backend_hi = -1 '\377', backend_lo = 65535, rnode = {spcNode = 1663, dbNode = 12397, relNode = 167948}}, rm =
{id= -3 '\375', dbId = 1663}, sn = {id = -3 '\375', dbId = 1663, relId = 12397}}, {id = -3 '\375', cc = {id = -3
'\375',dbId = 1663, hashValue = 12397}, cat = {id = -3 '\375', dbId = 1663, catId = 12397}, rc = {id = -3 '\375', dbId
=1663, relId = 12397}, sm = {id = -3 '\375', backend_hi = -1 '\377', backend_lo = 65535, rnode = {spcNode = 1663,
dbNode= 12397, relNode = 167947}}, rm = {id = -3 '\375', dbId = 1663}, sn = {id = -3 '\375', dbId = 1663, relId =
12397}},{id = -3 '\375', cc = {id = -3 '\375', dbId = 1663, hashValue = 12397}, cat = {id = -3 '\375', dbId = 1663,
catId= 12397}, rc = {id = -3 '\375', dbId = 1663, relId = 12397}, sm = {id = -3 '\375', backend_hi = -1 '\377',
backend_lo= 65535, rnode = {spcNode = 1663, dbNode = 12397, relNode = 167946}}, rm = {id = -3 '\375', dbId = 1663}, sn
={id = -3 '\375', dbId = 1663, relId = 12397}}, {id = 7 '\a', cc = {id = 7 '\a', dbId = 12397, hashValue = 1528188348},
cat= {id = 7 '\a', dbId = 12397, catId = 1528188348}, rc = {id = 7 '\a', dbId = 12397, relId = 1528188348}, sm = {id =
7'\a', backend_hi = -10 '\366', backend_lo = 58325, rnode = {spcNode = 12397, dbNode = 1528188348, relNode = 22006}},
rm= {id = 7 '\a', dbId = 12397}, sn = {id = 7 '\a', dbId = 12397, relId = 1528188348}}, {id = 6 '\006', cc = {id = 6
'\006',dbId = 12397, hashValue = 2483940397}, cat = {id = 6 '\006', dbId = 12397, catId = 2483940397}, rc = {id = 6
'\006',dbId = 12397, relId = 2483940397}, sm = {id = 6 '\006', backend_hi = 7 '\a', backend_lo = 58326, rnode =
{spcNode= 12397, dbNode = 2483940397, relNode = 22006}}, rm = {id = 6 '\006', dbId = 12397}, sn = {id = 6 '\006', dbId
=12397, relId = 2483940397}}, {id = 7 '\a', cc = {id = 7 '\a', dbId = 12397, hashValue = 37473943}, cat = {id = 7 '\a',
dbId= 12397, catId = 37473943}, rc = {id = 7 '\a', dbId = 12397, relId = 37473943}, sm = {id = 7 '\a', backend_hi = -10
'\366',backend_lo = 58325, rnode = {spcNode = 12397, dbNode = 37473943, relNode = 22006}}, rm = {id = 7 '\a', dbId =
12397},sn = {id = 7 '\a', dbId = 12397, relId = 37473943}}, {id = 6 '\006', cc = {id = 6 '\006', dbId = 12397,
hashValue= 2828489776}, cat = {id = 6 '\006', dbId = 12397, catId = 2828489776}, rc = {id = 6 '\006', dbId = 12397,
relId= 2828489776}, sm = {id = 6 '\006', backend_hi = 7 '\a', backend_lo = 58326, rnode = {spcNode = 12397, dbNode =
2828489776,relNode = 22006}}, rm = {id = 6 '\006', dbId = 12397}, sn = {id = 6 '\006', dbId = 12397, relId =
2828489776}},{id = 7 '\a', cc = {id = 7 '\a', dbId = 12397, hashValue = 2277595885}, cat = {id = 7 '\a', dbId = 12397,
catId= 2277595885}, rc = {id = 7 '\a', dbId = 12397, relId = 2277595885}, sm = {id = 7 '\a', backend_hi = -10 '\366',
backend_lo= 58325, rnode = {spcNode = 12397, dbNode = 2277595885, relNode = 22006}}, rm = {id = 7 '\a', dbId = 12397},
sn= {id = 7 '\a', dbId = 12397, relId = 2277595885}}, {id = 6 '\006', cc = {id = 6 '\006', dbId = 12397, hashValue =
3442084044},cat = {id = 6 '\006', dbId = 12397, catId = 3442084044}, rc = {id = 6 '\006', dbId = 12397, relId =
3442084044},sm = {id = 6 '\006', backend_hi = 7 '\a', backend_lo = 58326, rnode = {spcNode = 12397, dbNode =
3442084044,relNode = 22006}}, rm = {id = 6 '\006', dbId = 12397}, sn = {id = 6 '\006', dbId = 12397, relId =
3442084044}},{id = 7 '\a', cc = {id = 7 '\a', dbId = 12397, hashValue = 2945592578}, cat = {id = 7 '\a', dbId = 12397,
catId= 2945592578}, rc = {id = 7 '\a', dbId = 12397, relId = 2945592578}, sm = {id = 7 '\a', backend_hi = -10 '\366',
backend_lo= 58325, rnode = {spcNode = 12397, dbNode = 2945592578, relNode = 22006}}, rm = {id = 7 '\a', dbId = 12397},
sn= {id = 7 '\a', dbId = 12397, relId = 2945592578}}, {id = 6 '\006', cc = {id = 6 '\006', dbId = 12397, hashValue =
134785355},cat = {id = 6 '\006', dbId = 12397, catId = 134785355}, rc = {id = 6 '\006', dbId = 12397, relId =
134785355},sm = {id = 6 '\006', backend_hi = 7 '\a', backend_lo = 58326, rnode = {spcNode = 12397, dbNode = 134785355,
relNode= 22006}}, rm = {id = 6 '\006', dbId = 12397}, sn = {id = 6 '\006', dbId = 12397, relId = 134785355}}, {id = 7
'\a',cc = {id = 7 '\a', dbId = 12397, hashValue = 2621623531}, cat = {id = 7 '\a', dbId = 12397, catId = 2621623531},
rc= {id = 7 '\a', dbId = 12397, relId = 2621623531}, sm = {id = 7 '\a', backend_hi = -10 '\366', backend_lo = 58325,
rnode= {spcNode = 12397, dbNode = 2621623531, relNode = 22006}}, rm = {id = 7 '\a', dbId = 12397}, sn = {id = 7 '\a',
dbId= 12397, relId = 2621623531}}, {id = 6 '\006', cc = {id = 6 '\006', dbId = 12397, hashValue = 3549520513}, cat =
{id= 6 '\006', dbId = 12397, catId = 3549520513}, rc = {id = 6 '\006', dbId = 12397, relId = 3549520513}, sm = {id = 6
'\006',backend_hi = 7 '\a', backend_lo = 58326, rnode = {spcNode = 12397, dbNode = 3549520513, relNode = 22006}}, rm =
{id= 6 '\006', dbId = 12397}, sn = {id = 6 '\006', dbId = 12397, relId = 3549520513}}, {id = -2 '\376', cc = {id = -2
'\376',dbId = 12397, hashValue = 167949}, cat = {id = -2 '\376', dbId = 12397, catId = 167949}, rc = {id = -2 '\376',
dbId= 12397, relId = 167949}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode =
12397,dbNode = 167949, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId =
167949}},{id = -5 '\373', cc = {id = -5 '\373', dbId = 12397, hashValue = 2608}, cat = {id = -5 '\373', dbId = 12397,
catId= 2608}, rc = {id = -5 '\373', dbId = 12397, relId = 2608}, sm = {id = -5 '\373', backend_hi = -37 '\333',
backend_lo= 3348, rnode = {spcNode = 12397, dbNode = 2608, relNode = 11}}, rm = {id = -5 '\373', dbId = 12397}, sn =
{id= -5 '\373', dbId = 12397, relId = 2608}}} 
        nextmsg = 1
        nummsgs = 20
        __func__ = "ReceiveSharedInvalidMessages"
#35 0x000055f6e5729223 in AcceptInvalidationMessages () at
/home/andres/src/postgresql/src/backend/utils/cache/inval.c:681
No locals.
#36 0x000055f6e55b6825 in LockRelationOid (relid=1259, lockmode=1) at
/home/andres/src/postgresql/src/backend/storage/lmgr/lmgr.c:125
        tag = {locktag_field1 = 12397, locktag_field2 = 1259, locktag_field3 = 0, locktag_field4 = 0, locktag_type = 0
'\000',locktag_lockmethodid = 1 '\001'} 
        res = LOCKACQUIRE_OK
#37 0x000055f6e51e11f8 in relation_open (relationId=1259, lockmode=1) at
/home/andres/src/postgresql/src/backend/access/heap/heapam.c:1132
        r = 0x55f6e5750d79 <fmgr_info+41>
        __func__ = "relation_open"
#38 0x000055f6e51e14bd in heap_open (relationId=1259, lockmode=1) at
/home/andres/src/postgresql/src/backend/access/heap/heapam.c:1298
        r = 0xb8e74132f0
        __func__ = "heap_open"
#39 0x000055f6e57331d6 in ScanPgRelation (targetRelId=16386, indexOK=true, force_non_historic=false) at
/home/andres/src/postgresql/src/backend/utils/cache/relcache.c:341
        pg_class_tuple = 0x0
        pg_class_desc = 0x55f6e7415350
        pg_class_scan = 0x55f6e74142d0
        key = {{sk_flags = 0, sk_attno = -2, sk_strategy = 3, sk_subtype = 0, sk_collation = 100, sk_func = {fn_addr =
0x55f6e569cbf8<oideq>, fn_oid = 184, fn_nargs = 2, fn_strict = true, fn_retset = false, fn_stats = 2 '\002', fn_extra =
0x0,fn_mcxt = 0x55f6e743c570, fn_expr = 0x0}, sk_argument = 16386}} 
        snapshot = 0x10
        __func__ = "ScanPgRelation"
#40 0x000055f6e5734b6f in RelationBuildDesc (targetRelId=16386, insertIt=false) at
/home/andres/src/postgresql/src/backend/utils/cache/relcache.c:1082
        relation = 0x0
        relid = 32525
        pg_class_tuple = 0x55f6e5aae2c0 <TopTransactionStateData>
        relp = 0x55f6e7415360
        __func__ = "RelationBuildDesc"
#41 0x000055f6e5737557 in RelationClearRelation (relation=0x7f0de3d56980, rebuild=true) at
/home/andres/src/postgresql/src/backend/utils/cache/relcache.c:2446
        save_relid = 16386
        keep_tupdesc = false
        keep_partkey = 246
        newrel = 0x55f6e73f0900
        keep_rules = false
        keep_policies = 85
        keep_partdesc = 231
        __func__ = "RelationClearRelation"
#42 0x000055f6e5737aaf in RelationFlushRelation (relation=0x7f0de3d56980) at
/home/andres/src/postgresql/src/backend/utils/cache/relcache.c:2584
        rebuild = true
#43 0x000055f6e5737bc8 in RelationCacheInvalidateEntry (relationId=16386) at
/home/andres/src/postgresql/src/backend/utils/cache/relcache.c:2636
        relation = 0x7f0de3d56980
#44 0x000055f6e5728fe4 in LocalExecuteInvalidationMessage (msg=0x7ffc0d14dc70) at
/home/andres/src/postgresql/src/backend/utils/cache/inval.c:587
        i = 9
        __func__ = "LocalExecuteInvalidationMessage"
#45 0x000055f6e55b27c0 in ReceiveSharedInvalidMessages (invalFunction=0x55f6e5728edd <LocalExecuteInvalidationMessage>,
resetFunction=0x55f6e5729149<InvalidateSystemCaches>) at
/home/andres/src/postgresql/src/backend/storage/ipc/sinval.c:121
        msg = {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 16386}, cat = {id = -2 '\376', dbId =
12397,catId = 16386}, rc = {id = -2 '\376', dbId = 12397, relId = 16386}, sm = {id = -2 '\376', backend_hi = -114
'\216',backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 16386, relNode = 0}}, rm = {id = -2 '\376', dbId =
12397},sn = {id = -2 '\376', dbId = 12397, relId = 16386}} 
        getResult = 9
        messages = {{id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 1259}, cat = {id = -2 '\376', dbId
=12397, catId = 1259}, rc = {id = -2 '\376', dbId = 12397, relId = 1259}, sm = {id = -2 '\376', backend_hi = -114
'\216',backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 1259, relNode = 22006}}, rm = {id = -2 '\376', dbId =
12397},sn = {id = -2 '\376', dbId = 12397, relId = 1259}}, {id = -5 '\373', cc = {id = -5 '\373', dbId = 12397,
hashValue= 2608}, cat = {id = -5 '\373', dbId = 12397, catId = 2608}, rc = {id = -5 '\373', dbId = 12397, relId =
2608},sm = {id = -5 '\373', backend_hi = -37 '\333', backend_lo = 3348, rnode = {spcNode = 12397, dbNode = 2608,
relNode= 11}}, rm = {id = -5 '\373', dbId = 12397}, sn = {id = -5 '\373', dbId = 12397, relId = 2608}}, {id = -2
'\376',cc = {id = -2 '\376', dbId = 12397, hashValue = 1259}, cat = {id = -2 '\376', dbId = 12397, catId = 1259}, rc =
{id= -2 '\376', dbId = 12397, relId = 1259}, sm = {id = -2 '\376', backend_hi = -38 '\332', backend_lo = 3348, rnode =
{spcNode= 12397, dbNode = 1259, relNode = 22006}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId =
12397,relId = 1259}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 3455}, cat = {id = -2 '\376',
dbId= 12397, catId = 3455}, rc = {id = -2 '\376', dbId = 12397, relId = 3455}, sm = {id = -2 '\376', backend_hi = -114
'\216',backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 3455, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397},
sn= {id = -2 '\376', dbId = 12397, relId = 3455}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue =
3455},cat = {id = -2 '\376', dbId = 12397, catId = 3455}, rc = {id = -2 '\376', dbId = 12397, relId = 3455}, sm = {id =
-2'\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 3455, relNode = 22006}}, rm
={id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 3455}}, {id = -2 '\376', cc = {id = -2
'\376',dbId = 12397, hashValue = 1259}, cat = {id = -2 '\376', dbId = 12397, catId = 1259}, rc = {id = -2 '\376', dbId
=12397, relId = 1259}, sm = {id = -2 '\376', backend_hi = -38 '\332', backend_lo = 3348, rnode = {spcNode = 12397,
dbNode= 1259, relNode = 22006}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId =
1259}},{id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 2663}, cat = {id = -2 '\376', dbId = 12397,
catId= 2663}, rc = {id = -2 '\376', dbId = 12397, relId = 2663}, sm = {id = -2 '\376', backend_hi = -114 '\216',
backend_lo= 58738, rnode = {spcNode = 12397, dbNode = 2663, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn =
{id= -2 '\376', dbId = 12397, relId = 2663}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 2663},
cat= {id = -2 '\376', dbId = 12397, catId = 2663}, rc = {id = -2 '\376', dbId = 12397, relId = 2663}, sm = {id = -2
'\376',backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 2663, relNode = 22006}}, rm =
{id= -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 2663}}, {id = -2 '\376', cc = {id = -2
'\376',dbId = 12397, hashValue = 1259}, cat = {id = -2 '\376', dbId = 12397, catId = 1259}, rc = {id = -2 '\376', dbId
=12397, relId = 1259}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397,
dbNode= 1259, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 1259}},
{id= -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 2662}, cat = {id = -2 '\376', dbId = 12397, catId =
2662},rc = {id = -2 '\376', dbId = 12397, relId = 2662}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo =
58738,rnode = {spcNode = 12397, dbNode = 2662, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2
'\376',dbId = 12397, relId = 2662}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 2662}, cat = {id
=-2 '\376', dbId = 12397, catId = 2662}, rc = {id = -2 '\376', dbId = 12397, relId = 2662}, sm = {id = -2 '\376',
backend_hi= -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 2662, relNode = 22006}}, rm = {id = -2
'\376',dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 2662}}, {id = -2 '\376', cc = {id = -2 '\376', dbId =
12397,hashValue = 1259}, cat = {id = -2 '\376', dbId = 12397, catId = 1259}, rc = {id = -2 '\376', dbId = 12397, relId
=1259}, sm = {id = -2 '\376', backend_hi = 0 '\000', backend_lo = 0, rnode = {spcNode = 12397, dbNode = 1259, relNode =
32525}},rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 1259}}, {id = -2 '\376', cc =
{id= -2 '\376', dbId = 12397, hashValue = 167949}, cat = {id = -2 '\376', dbId = 12397, catId = 167949}, rc = {id = -2
'\376',dbId = 12397, relId = 167949}, sm = {id = -2 '\376', backend_hi = 0 '\000', backend_lo = 0, rnode = {spcNode =
12397,dbNode = 167949, relNode = 11}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId =
167949}},{id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 167949}, cat = {id = -2 '\376', dbId = 12397,
catId= 167949}, rc = {id = -2 '\376', dbId = 12397, relId = 167949}, sm = {id = -2 '\376', backend_hi = 0 '\000',
backend_lo= 0, rnode = {spcNode = 12397, dbNode = 167949, relNode = 32525}}, rm = {id = -2 '\376', dbId = 12397}, sn =
{id= -2 '\376', dbId = 12397, relId = 167949}}, {id = -5 '\373', cc = {id = -5 '\373', dbId = 12397, hashValue = 2608},
cat= {id = -5 '\373', dbId = 12397, catId = 2608}, rc = {id = -5 '\373', dbId = 12397, relId = 2608}, sm = {id = -5
'\373',backend_hi = -41 '\327', backend_lo = 3348, rnode = {spcNode = 12397, dbNode = 2608, relNode = 11}}, rm = {id =
-5'\373', dbId = 12397}, sn = {id = -5 '\373', dbId = 12397, relId = 2608}}, {id = -2 '\376', cc = {id = -2 '\376',
dbId= 12397, hashValue = 167949}, cat = {id = -2 '\376', dbId = 12397, catId = 167949}, rc = {id = -2 '\376', dbId =
12397,relId = 167949}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397,
dbNode= 167949, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId =
167949}},{id = -3 '\375', cc = {id = -3 '\375', dbId = 1663, hashValue = 12397}, cat = {id = -3 '\375', dbId = 1663,
catId= 12397}, rc = {id = -3 '\375', dbId = 1663, relId = 12397}, sm = {id = -3 '\375', backend_hi = -1 '\377',
backend_lo= 65535, rnode = {spcNode = 1663, dbNode = 12397, relNode = 167943}}, rm = {id = -3 '\375', dbId = 1663}, sn
={id = -3 '\375', dbId = 1663, relId = 12397}}, {id = -3 '\375', cc = {id = -3 '\375', dbId = 1663, hashValue = 12397},
cat= {id = -3 '\375', dbId = 1663, catId = 12397}, rc = {id = -3 '\375', dbId = 1663, relId = 12397}, sm = {id = -3
'\375',backend_hi = -1 '\377', backend_lo = 65535, rnode = {spcNode = 1663, dbNode = 12397, relNode = 167948}}, rm =
{id= -3 '\375', dbId = 1663}, sn = {id = -3 '\375', dbId = 1663, relId = 12397}}, {id = -3 '\375', cc = {id = -3
'\375',dbId = 1663, hashValue = 12397}, cat = {id = -3 '\375', dbId = 1663, catId = 12397}, rc = {id = -3 '\375', dbId
=1663, relId = 12397}, sm = {id = -3 '\375', backend_hi = -1 '\377', backend_lo = 65535, rnode = {spcNode = 1663,
dbNode= 12397, relNode = 167947}}, rm = {id = -3 '\375', dbId = 1663}, sn = {id = -3 '\375', dbId = 1663, relId =
12397}},{id = -3 '\375', cc = {id = -3 '\375', dbId = 1663, hashValue = 12397}, cat = {id = -3 '\375', dbId = 1663,
catId= 12397}, rc = {id = -3 '\375', dbId = 1663, relId = 12397}, sm = {id = -3 '\375', backend_hi = -1 '\377',
backend_lo= 65535, rnode = {spcNode = 1663, dbNode = 12397, relNode = 167946}}, rm = {id = -3 '\375', dbId = 1663}, sn
={id = -3 '\375', dbId = 1663, relId = 12397}}, {id = 7 '\a', cc = {id = 7 '\a', dbId = 12397, hashValue = 1528188348},
cat= {id = 7 '\a', dbId = 12397, catId = 1528188348}, rc = {id = 7 '\a', dbId = 12397, relId = 1528188348}, sm = {id =
7'\a', backend_hi = -10 '\366', backend_lo = 58325, rnode = {spcNode = 12397, dbNode = 1528188348, relNode = 22006}},
rm= {id = 7 '\a', dbId = 12397}, sn = {id = 7 '\a', dbId = 12397, relId = 1528188348}}, {id = 6 '\006', cc = {id = 6
'\006',dbId = 12397, hashValue = 2483940397}, cat = {id = 6 '\006', dbId = 12397, catId = 2483940397}, rc = {id = 6
'\006',dbId = 12397, relId = 2483940397}, sm = {id = 6 '\006', backend_hi = 7 '\a', backend_lo = 58326, rnode =
{spcNode= 12397, dbNode = 2483940397, relNode = 22006}}, rm = {id = 6 '\006', dbId = 12397}, sn = {id = 6 '\006', dbId
=12397, relId = 2483940397}}, {id = 7 '\a', cc = {id = 7 '\a', dbId = 12397, hashValue = 37473943}, cat = {id = 7 '\a',
dbId= 12397, catId = 37473943}, rc = {id = 7 '\a', dbId = 12397, relId = 37473943}, sm = {id = 7 '\a', backend_hi = -10
'\366',backend_lo = 58325, rnode = {spcNode = 12397, dbNode = 37473943, relNode = 22006}}, rm = {id = 7 '\a', dbId =
12397},sn = {id = 7 '\a', dbId = 12397, relId = 37473943}}, {id = 6 '\006', cc = {id = 6 '\006', dbId = 12397,
hashValue= 2828489776}, cat = {id = 6 '\006', dbId = 12397, catId = 2828489776}, rc = {id = 6 '\006', dbId = 12397,
relId= 2828489776}, sm = {id = 6 '\006', backend_hi = 7 '\a', backend_lo = 58326, rnode = {spcNode = 12397, dbNode =
2828489776,relNode = 22006}}, rm = {id = 6 '\006', dbId = 12397}, sn = {id = 6 '\006', dbId = 12397, relId =
2828489776}},{id = 7 '\a', cc = {id = 7 '\a', dbId = 12397, hashValue = 2277595885}, cat = {id = 7 '\a', dbId = 12397,
catId= 2277595885}, rc = {id = 7 '\a', dbId = 12397, relId = 2277595885}, sm = {id = 7 '\a', backend_hi = -10 '\366',
backend_lo= 58325, rnode = {spcNode = 12397, dbNode = 2277595885, relNode = 22006}}, rm = {id = 7 '\a', dbId = 12397},
sn= {id = 7 '\a', dbId = 12397, relId = 2277595885}}, {id = 6 '\006', cc = {id = 6 '\006', dbId = 12397, hashValue =
3442084044},cat = {id = 6 '\006', dbId = 12397, catId = 3442084044}, rc = {id = 6 '\006', dbId = 12397, relId =
3442084044},sm = {id = 6 '\006', backend_hi = 7 '\a', backend_lo = 58326, rnode = {spcNode = 12397, dbNode =
3442084044,relNode = 22006}}, rm = {id = 6 '\006', dbId = 12397}, sn = {id = 6 '\006', dbId = 12397, relId =
3442084044}},{id = 7 '\a', cc = {id = 7 '\a', dbId = 12397, hashValue = 2945592578}, cat = {id = 7 '\a', dbId = 12397,
catId= 2945592578}, rc = {id = 7 '\a', dbId = 12397, relId = 2945592578}, sm = {id = 7 '\a', backend_hi = -10 '\366',
backend_lo= 58325, rnode = {spcNode = 12397, dbNode = 2945592578, relNode = 22006}}, rm = {id = 7 '\a', dbId = 12397},
sn= {id = 7 '\a', dbId = 12397, relId = 2945592578}}, {id = 6 '\006', cc = {id = 6 '\006', dbId = 12397, hashValue =
134785355},cat = {id = 6 '\006', dbId = 12397, catId = 134785355}, rc = {id = 6 '\006', dbId = 12397, relId =
134785355},sm = {id = 6 '\006', backend_hi = 7 '\a', backend_lo = 58326, rnode = {spcNode = 12397, dbNode = 134785355,
relNode= 22006}}, rm = {id = 6 '\006', dbId = 12397}, sn = {id = 6 '\006', dbId = 12397, relId = 134785355}}, {id = 7
'\a',cc = {id = 7 '\a', dbId = 12397, hashValue = 2621623531}, cat = {id = 7 '\a', dbId = 12397, catId = 2621623531},
rc= {id = 7 '\a', dbId = 12397, relId = 2621623531}, sm = {id = 7 '\a', backend_hi = -10 '\366', backend_lo = 58325,
rnode= {spcNode = 12397, dbNode = 2621623531, relNode = 22006}}, rm = {id = 7 '\a', dbId = 12397}, sn = {id = 7 '\a',
dbId= 12397, relId = 2621623531}}, {id = 6 '\006', cc = {id = 6 '\006', dbId = 12397, hashValue = 3549520513}, cat =
{id= 6 '\006', dbId = 12397, catId = 3549520513}, rc = {id = 6 '\006', dbId = 12397, relId = 3549520513}, sm = {id = 6
'\006',backend_hi = 7 '\a', backend_lo = 58326, rnode = {spcNode = 12397, dbNode = 3549520513, relNode = 22006}}, rm =
{id= 6 '\006', dbId = 12397}, sn = {id = 6 '\006', dbId = 12397, relId = 3549520513}}, {id = -2 '\376', cc = {id = -2
'\376',dbId = 12397, hashValue = 167949}, cat = {id = -2 '\376', dbId = 12397, catId = 167949}, rc = {id = -2 '\376',
dbId= 12397, relId = 167949}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode =
12397,dbNode = 167949, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId =
167949}},{id = -5 '\373', cc = {id = -5 '\373', dbId = 12397, hashValue = 2608}, cat = {id = -5 '\373', dbId = 12397,
catId= 2608}, rc = {id = -5 '\373', dbId = 12397, relId = 2608}, sm = {id = -5 '\373', backend_hi = -37 '\333',
backend_lo= 3348, rnode = {spcNode = 12397, dbNode = 2608, relNode = 11}}, rm = {id = -5 '\373', dbId = 12397}, sn =
{id= -5 '\373', dbId = 12397, relId = 2608}}} 
        nextmsg = 1
        nummsgs = 20
        __func__ = "ReceiveSharedInvalidMessages"
#46 0x000055f6e5729223 in AcceptInvalidationMessages () at
/home/andres/src/postgresql/src/backend/utils/cache/inval.c:681
No locals.
#47 0x000055f6e55b6825 in LockRelationOid (relid=16384, lockmode=3) at
/home/andres/src/postgresql/src/backend/storage/lmgr/lmgr.c:125
        tag = {locktag_field1 = 12397, locktag_field2 = 16384, locktag_field3 = 0, locktag_field4 = 0, locktag_type = 0
'\000',locktag_lockmethodid = 1 '\001'} 
        res = LOCKACQUIRE_OK
#48 0x000055f6e5386187 in lock_and_open_sequence (seq=0x55f6e743fed0) at
/home/andres/src/postgresql/src/backend/commands/sequence.c:1059
        currentOwner = 0x55f6e73b0990
        thislxid = 200412
#49 0x000055f6e538629e in init_sequence (relid=16384, p_elm=0x7ffc0d14de38, p_rel=0x7ffc0d14de30) at
/home/andres/src/postgresql/src/backend/commands/sequence.c:1124
        elm = 0x55f6e743fed0
        seqrel = 0x60
        found = true
        __func__ = "init_sequence"
#50 0x000055f6e5385032 in nextval_internal (relid=16384, check_permissions=true) at
/home/andres/src/postgresql/src/backend/commands/sequence.c:592
        elm = 0x55f6e577962e <AllocSetAlloc+698>
        seqrel = 0x7ffc0d14e0a0
        buf = 0
        page = 0x4d430000 <error: Cannot access memory at address 0x4d430000>
        pgstuple = 0x55f6e5723c42 <int4hashfast+23>
        pgsform = 0x7ffc0d14dea0
        seqdatatuple = {t_len = 16, t_self = {ip_blkid = {bi_hi = 0, bi_lo = 0}, ip_posid = 42336}, t_tableOid = 22006,
t_data= 0x0} 
        seq = 0x55f6e743ac78
        incby = -3334848951855292406
        maxv = 94518896342214
        minv = 99003719328
        cache = 94518930289304
        log = 94518929721808
        fetch = 139697633736304
        last = 94518929721808
        result = 23
        next = 94518899785832
        rescnt = 0
        cycle = false
        logit = false
        __func__ = "nextval_internal"
#51 0x000055f6e5384fec in nextval_oid (fcinfo=0x55f6e743b810) at
/home/andres/src/postgresql/src/backend/commands/sequence.c:564
        relid = 16384
#52 0x000055f6e53de11b in ExecInterpExpr (state=0x55f6e743b2b8, econtext=0x55f6e743af08, isnull=0x7ffc0d14e1d7) at
/home/andres/src/postgresql/src/backend/executor/execExprInterp.c:678
        fcinfo = 0x55f6e743b810
        argnull = 0x55f6e743bb50
        argno = 1
        d = 94518903500096
        op = 0x55f6e743bc28
        resultslot = 0x55f6e743b1b8
        innerslot = 0x0
        outerslot = 0x0
        scanslot = 0x0
        dispatch_table = {0x55f6e53dd811 <ExecInterpExpr+148>, 0x55f6e53dd838 <ExecInterpExpr+187>, 0x55f6e53dd85b
<ExecInterpExpr+222>,0x55f6e53dd87e <ExecInterpExpr+257>, 0x55f6e53dd8a1 <ExecInterpExpr+292>, 0x55f6e53dd92e
<ExecInterpExpr+433>,0x55f6e53dd9bb <ExecInterpExpr+574>, 0x55f6e53dda48 <ExecInterpExpr+715>, 0x55f6e53ddaf9
<ExecInterpExpr+892>,0x55f6e53ddbaa <ExecInterpExpr+1069>, 0x55f6e53ddc67 <ExecInterpExpr+1258>, 0x55f6e53ddc95
<ExecInterpExpr+1304>,0x55f6e53ddd5a <ExecInterpExpr+1501>, 0x55f6e53dde1f <ExecInterpExpr+1698>, 0x55f6e53ddee4
<ExecInterpExpr+1895>,0x55f6e53ddf48 <ExecInterpExpr+1995>, 0x55f6e53ddffa <ExecInterpExpr+2173>, 0x55f6e53de030
<ExecInterpExpr+2227>,0x55f6e53de09d <ExecInterpExpr+2336>, 0x55f6e53de15a <ExecInterpExpr+2525>, 0x55f6e53de188
<ExecInterpExpr+2571>,0x55f6e53de1b6 <ExecInterpExpr+2617>, 0x55f6e53de1c1 <ExecInterpExpr+2628>, 0x55f6e53de229
<ExecInterpExpr+2732>,0x55f6e53de282 <ExecInterpExpr+2821>, 0x55f6e53de28d <ExecInterpExpr+2832>, 0x55f6e53de2f5
<ExecInterpExpr+2936>,0x55f6e53de34e <ExecInterpExpr+3025>, 0x55f6e53de386 <ExecInterpExpr+3081>, 0x55f6e53de3fb
<ExecInterpExpr+3198>,0x55f6e53de426 <ExecInterpExpr+3241>, 0x55f6e53de471 <ExecInterpExpr+3316>, 0x55f6e53de4bf
<ExecInterpExpr+3394>,0x55f6e53de51a <ExecInterpExpr+3485>, 0x55f6e53de55c <ExecInterpExpr+3551>, 0x55f6e53de5a1
<ExecInterpExpr+3620>,0x55f6e53de5cf <ExecInterpExpr+3666>, 0x55f6e53de5fd <ExecInterpExpr+3712>, 0x55f6e53de637
<ExecInterpExpr+3770>,0x55f6e53de69a <ExecInterpExpr+3869>, 0x55f6e53de6fd <ExecInterpExpr+3968>, 0x55f6e53de737
<ExecInterpExpr+4026>,0x55f6e53de765 <ExecInterpExpr+4072>, 0x55f6e53de793 <ExecInterpExpr+4118>, 0x55f6e53de7c3
<ExecInterpExpr+4166>,0x55f6e53de8af <ExecInterpExpr+4402>, 0x55f6e53de905 <ExecInterpExpr+4488>, 0x55f6e53deb11
<ExecInterpExpr+5012>,0x55f6e53dec10 <ExecInterpExpr+5267>, 0x55f6e53ded00 <ExecInterpExpr+5507>, 0x55f6e53dede9
<ExecInterpExpr+5740>,0x55f6e53dee10 <ExecInterpExpr+5779>, 0x55f6e53dee37 <ExecInterpExpr+5818>, 0x55f6e53dee5e
<ExecInterpExpr+5857>,0x55f6e53dee85 <ExecInterpExpr+5896>, 0x55f6e53deeb3 <ExecInterpExpr+5942>, 0x55f6e53deeda
<ExecInterpExpr+5981>,0x55f6e53df026 <ExecInterpExpr+6313>, 0x55f6e53df13b <ExecInterpExpr+6590>, 0x55f6e53df162
<ExecInterpExpr+6629>,0x55f6e53df190 <ExecInterpExpr+6675>, 0x55f6e53df1be <ExecInterpExpr+6721>, 0x55f6e53df1ec
<ExecInterpExpr+6767>,0x55f6e53df242 <ExecInterpExpr+6853>, 0x55f6e53df269 <ExecInterpExpr+6892>, 0x55f6e53df290
<ExecInterpExpr+6931>,0x55f6e53de839 <ExecInterpExpr+4284>, 0x55f6e53df30c <ExecInterpExpr+7055>, 0x55f6e53df333
<ExecInterpExpr+7094>,0x55f6e53df2b7 <ExecInterpExpr+6970>, 0x55f6e53df2e5 <ExecInterpExpr+7016>, 0x55f6e53df35a
<ExecInterpExpr+7133>,0x55f6e53df381 <ExecInterpExpr+7172>, 0x55f6e53df424 <ExecInterpExpr+7335>, 0x55f6e53df44b
<ExecInterpExpr+7374>,0x55f6e53df4ee <ExecInterpExpr+7537>, 0x55f6e53df51c <ExecInterpExpr+7583>, 0x55f6e53df54a
<ExecInterpExpr+7629>,0x55f6e53df598 <ExecInterpExpr+7707>, 0x55f6e53df63b <ExecInterpExpr+7870>, 0x55f6e53df6c1
<ExecInterpExpr+8004>,0x55f6e53df7b0 <ExecInterpExpr+8243>, 0x55f6e53df846 <ExecInterpExpr+8393>, 0x55f6e53df9e2
<ExecInterpExpr+8805>,0x55f6e53dfbd6 <ExecInterpExpr+9305>, 0x55f6e53dfc04 <ExecInterpExpr+9351>, 0x55f6e53dfc32
<ExecInterpExpr+9397>}
#53 0x000055f6e53dfcae in ExecInterpExprStillValid (state=0x55f6e743b2b8, econtext=0x55f6e743af08,
isNull=0x7ffc0d14e1d7)at /home/andres/src/postgresql/src/backend/executor/execExprInterp.c:1786 
No locals.
#54 0x000055f6e542225e in ExecEvalExprSwitchContext (state=0x55f6e743b2b8, econtext=0x55f6e743af08,
isNull=0x7ffc0d14e1d7)at /home/andres/src/postgresql/src/include/executor/executor.h:303 
        retDatum = 128
        oldContext = 0x55f6e743a560
#55 0x000055f6e54222c7 in ExecProject (projInfo=0x55f6e743b2b0) at
/home/andres/src/postgresql/src/include/executor/executor.h:337
        econtext = 0x55f6e743af08
        state = 0x55f6e743b2b8
        slot = 0x55f6e743b1b8
        isnull = false
#56 0x000055f6e542249e in ExecResult (pstate=0x55f6e743adf0) at
/home/andres/src/postgresql/src/backend/executor/nodeResult.c:136
        node = 0x55f6e743adf0
        outerTupleSlot = 0x940
        outerPlan = 0x0
        econtext = 0x55f6e743af08
#57 0x000055f6e53f2c42 in ExecProcNodeFirst (node=0x55f6e743adf0) at
/home/andres/src/postgresql/src/backend/executor/execProcnode.c:445
No locals.
#58 0x000055f6e541c327 in ExecProcNode (node=0x55f6e743adf0) at
/home/andres/src/postgresql/src/include/executor/executor.h:237
No locals.
#59 0x000055f6e541f327 in ExecModifyTable (pstate=0x55f6e743a9e0) at
/home/andres/src/postgresql/src/backend/executor/nodeModifyTable.c:2027
        node = 0x55f6e743a9e0
        proute = 0x0
        estate = 0x55f6e743a678
        operation = CMD_INSERT
        saved_resultRelInfo = 0x0
        resultRelInfo = 0x55f6e743a8c8
        subplanstate = 0x55f6e743adf0
        junkfilter = 0x0
        slot = 0x7ffc0d14e430
        planSlot = 0x55f6e743a678
        tupleid = 0x55f6e743c078
        tuple_ctid = {ip_blkid = {bi_hi = 58687, bi_lo = 22006}, ip_posid = 0}
        oldtupdata = {t_len = 3846304154, t_self = {ip_blkid = {bi_hi = 22006, bi_lo = 0}, ip_posid = 0}, t_tableOid =
0,t_data = 0x7ffc0d14e320} 
        oldtuple = 0x0
        __func__ = "ExecModifyTable"
#60 0x000055f6e53f2c42 in ExecProcNodeFirst (node=0x55f6e743a9e0) at
/home/andres/src/postgresql/src/backend/executor/execProcnode.c:445
No locals.
#61 0x000055f6e53e7aef in ExecProcNode (node=0x55f6e743a9e0) at
/home/andres/src/postgresql/src/include/executor/executor.h:237
No locals.
#62 0x000055f6e53ea4d9 in ExecutePlan (estate=0x55f6e743a678, planstate=0x55f6e743a9e0, use_parallel_mode=false,
operation=CMD_INSERT,sendTuples=false, numberTuples=0, direction=ForwardScanDirection, dest=0x55f6e73a7678,
execute_once=true)at /home/andres/src/postgresql/src/backend/executor/execMain.c:1721 
        slot = 0x55f6e73a73e0
        current_tuple_count = 0
#63 0x000055f6e53e80f6 in standard_ExecutorRun (queryDesc=0x55f6e739ef88, direction=ForwardScanDirection, count=0,
execute_once=true)at /home/andres/src/postgresql/src/backend/executor/execMain.c:362 
        estate = 0x55f6e743a678
        operation = CMD_INSERT
        dest = 0x55f6e73a7678
        sendTuples = false
        oldcontext = 0x55f6e739ee70
        __func__ = "standard_ExecutorRun"
#64 0x000055f6e53e7f0c in ExecutorRun (queryDesc=0x55f6e739ef88, direction=ForwardScanDirection, count=0,
execute_once=true)at /home/andres/src/postgresql/src/backend/executor/execMain.c:305 
No locals.
#65 0x000055f6e55dd7e6 in ProcessQuery (plan=0x55f6e73a7500, sourceText=0x55f6e737d438 "insert into t (b,c) values
(1,1);",params=0x0, queryEnv=0x0, dest=0x55f6e73a7678, completionTag=0x7ffc0d14e6d0 "") at
/home/andres/src/postgresql/src/backend/tcop/pquery.c:161
        queryDesc = 0x55f6e739ef88
#66 0x000055f6e55df188 in PortalRunMulti (portal=0x55f6e73e5038, isTopLevel=true, setHoldSnapshot=false,
dest=0x55f6e73a7678,altdest=0x55f6e73a7678, completionTag=0x7ffc0d14e6d0 "") at
/home/andres/src/postgresql/src/backend/tcop/pquery.c:1286
        pstmt = 0x55f6e73a7500
        active_snapshot_set = true
        stmtlist_item = 0x55f6e73a7618
#67 0x000055f6e55de742 in PortalRun (portal=0x55f6e73e5038, count=9223372036854775807, isTopLevel=true, run_once=true,
dest=0x55f6e73a7678,altdest=0x55f6e73a7678, completionTag=0x7ffc0d14e6d0 "") at
/home/andres/src/postgresql/src/backend/tcop/pquery.c:799
        save_exception_stack = 0x7ffc0d14e810
        save_context_stack = 0x0
        local_sigjmp_buf = {{__jmpbuf = {0, 2133478022532337521, 94518893857616, 140720527961408, 0, 0,
2133478022492491633,5300299599030161265}, __mask_was_saved = 0, __saved_mask = {__val = {94518900186830,
94518929721744,112, 4869, 94518929511200, 94518929684088, 112, 0, 0, 94518929948024, 0, 94518929684200, 112, 219473504,
94518929684088,94518929511200}}}} 
        result = false
        nprocessed = 0
        saveTopTransactionResourceOwner = 0x55f6e73ad0e8
        saveTopTransactionContext = 0x55f6e7403af0
        saveActivePortal = 0x0
        saveResourceOwner = 0x55f6e73ad0e8
        savePortalContext = 0x0
        saveMemoryContext = 0x55f6e7403af0
        __func__ = "PortalRun"
#68 0x000055f6e55d82fd in exec_simple_query (query_string=0x55f6e737d438 "insert into t (b,c) values (1,1);") at
/home/andres/src/postgresql/src/backend/tcop/postgres.c:1122
        parsetree = 0x55f6e737e308
        portal = 0x55f6e73e5038
        snapshot_set = true
        commandTag = 0x55f6e5971820 "INSERT"
        completionTag =
"\000\000\000\000\002\000\000\000\034\071v\345\366U\000\000\000\000\000\000\000\000\000\000P\330\067\347!\000\000\000
\347\024\r\374\177\000\000o@v\345\366U\000\000`\347\024\r\004\000\000\000\000\000\000\000\000\000\000"
        querytree_list = 0x55f6e737f098
        plantree_list = 0x55f6e73a7640
        receiver = 0x55f6e73a7678
        format = 0
        dest = DestRemote
        oldcontext = 0x55f6e7403af0
        parsetree_list = 0x55f6e737e368
        parsetree_item = 0x55f6e737e340
        save_log_statement_stats = false
        was_logged = false
        use_implicit_block = false
        msec_str =
"`\347\024\r\374\177\000\000\005\017v\345\366U\000\000\006\000\000\000!\000\000\000\070\324\067\347\366U\000"
        __func__ = "exec_simple_query"
#69 0x000055f6e55dc8ab in PostgresMain (argc=1, argv=0x55f6e73ab648, dbname=0x55f6e73ab540 "postgres",
username=0x55f6e73ab520"andres") at /home/andres/src/postgresql/src/backend/tcop/postgres.c:4159 
        query_string = 0x55f6e737d438 "insert into t (b,c) values (1,1);"
        firstchar = 81
        input_message = {data = 0x55f6e737d438 "insert into t (b,c) values (1,1);", len = 34, maxlen = 1024, cursor =
34}
        local_sigjmp_buf = {{__jmpbuf = {0, 2133478022354079601, 94518893857616, 140720527961408, 0, 0,
2133478022576377713,5300299600075067249}, __mask_was_saved = 1, __saved_mask = {__val = {0, 16, 0, 0, 0, 4869, 0,
33943971976,94518929516680, 94518929516656, 94518929511200, 140720527960336, 94518900188034, 94518929516680,
94518929516680,4870}}}} 
        send_ready_for_query = false
        disable_idle_in_transaction_timeout = false
        __func__ = "PostgresMain"
#70 0x000055f6e5535ce4 in BackendRun (port=0x55f6e73a10b0) at
/home/andres/src/postgresql/src/backend/postmaster/postmaster.c:4361
        av = 0x55f6e73ab648
        maxac = 2
        ac = 1
        secs = 587288130
        usecs = 313711
        i = 1
        __func__ = "BackendRun"
#71 0x000055f6e55353df in BackendStartup (port=0x55f6e73a10b0) at
/home/andres/src/postgresql/src/backend/postmaster/postmaster.c:4033
        bn = 0x55f6e73a0510
        pid = 0
        __func__ = "BackendStartup"
#72 0x000055f6e5531674 in ServerLoop () at /home/andres/src/postgresql/src/backend/postmaster/postmaster.c:1706
        port = 0x55f6e73a10b0
        i = 1
        rmask = {fds_bits = {16, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0}}
        selres = 1
        now = 1533972930
        readmask = {fds_bits = {24, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0}}
        nSockets = 5
        last_lockfile_recheck_time = 1533972883
        last_touch_time = 1533971868
        __func__ = "ServerLoop"
#73 0x000055f6e5530ea6 in PostmasterMain (argc=45, argv=0x55f6e7377340) at
/home/andres/src/postgresql/src/backend/postmaster/postmaster.c:1379
        opt = -1
        status = 0
        userDoption = 0x55f6e7399e50 "/srv/dev/pgdev-dev/"
        listen_addr_saved = true
        i = 64
        output_config_variable = 0x0
        __func__ = "PostmasterMain"
#74 0x000055f6e5456112 in main (argc=45, argv=0x55f6e7377340) at
/home/andres/src/postgresql/src/backend/main/main.c:228
        do_check_root = true

Greetings,

Andres Freund

Re: logical decoding / rewrite map vs. maxAllocatedDescs

От

Andres Freund

Дата:

11 августа 2018 г., 13:57:56

Hi,

On 2018-08-11 00:46:25 -0700, Andres Freund wrote:
> Below you can find the bt full showing a bunch of nested invalidations. Looking.

Hm. I wonder if the attached fixes the issue for you.  If it's this I
don't understand why this doesn't occur on older branches...

I've not yet been able to reliably reproduce the issue without the
patch, so I'm not sure it means much that it didn't reoccur afterwards.

- Andres

Вложения

patch.diff

Re: logical decoding / rewrite map vs. maxAllocatedDescs

От

Tomas Vondra

Дата:

11 августа 2018 г., 19:11:19


On 08/11/2018 09:34 AM, Andres Freund wrote:
> Hi,
> 
> On 2018-08-11 01:55:43 +0200, Tomas Vondra wrote:
>> On 08/10/2018 11:59 PM, Tomas Vondra wrote:
>>>
>>> ...
>>>
>>> I suspect there's some other ingredient, e.g. some manipulation with the
>>> subscription. Or maybe it's not needed at all and I'm just imagining things.
>>>
>>
>> Indeed, the manipulation with the subscription seems to be the key here.
>> I pretty reliably get the 'could not read block' error when doing this:
>>
>> 1) start the insert pgbench
>>
>>    pgbench -n -c 4 -T 300 -p 5433 -f insert.sql test
>>
>> 2) start the vacuum full pgbench
>>
>>    pgbench -n -f vacuum.sql -T 300 -p 5433 test
> 
> Just to be clear: 5433 is the subscriber, right? I tried it with both,
> but it's not clear what you meant with either the previous or the this
> email.
> 

Sorry for the confusion, 5433 was the publisher - I reinitialized the
cluster sometime after the initial report, and happened to swap the port
numbers. That is, both pgbench commands run on the publisher, while the
subscriber tries to sync the table (and fails due to duplicate values).

I can reproduce it pretty reliably, although it may take a couple of
sync tries from the subscriber.

regards

-- 
Tomas Vondra                  http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Re: logical decoding / rewrite map vs. maxAllocatedDescs

От

Tomas Vondra

Дата:

11 августа 2018 г., 19:14:59


On 08/11/2018 09:46 AM, Andres Freund wrote:
> On 2018-08-11 00:34:15 -0700, Andres Freund wrote:
>> I've run this numerous times now, and I haven't triggered it yet :/
> 
> Heh, I hit it literally seconds after hitting send:
> 
> 2018-08-11 00:35:52.804 PDT [2196][9/14864] LOG:  automatic analyze of table "postgres.pg_catalog.pg_depend" system
usage:CPU: user: 0.02 s, system: 0.00 s, elapsed: 0.15 s
 
> 2018-08-11 00:36:00.391 PDT [2196][9/14866] LOG:  automatic analyze of table "postgres.public.t" system usage: CPU:
user:0.25 s, system: 0.02 s, elapsed: 7.56 s
 
> 2018-08-11 00:36:00.399 PDT [2171][4/200412] PANIC:  could not read block 3 in file "base/12397/167946": read only 0
of8192 bytes
 
> 2018-08-11 00:36:00.399 PDT [2171][4/200412] STATEMENT:  insert into t (b,c) values (1,1);
> 2018-08-11 00:36:00.410 PDT [2196][9/14868] LOG:  skipping vacuum of "pg_class" --- lock not available
> 2018-08-11 00:36:00.448 PDT [389][] LOG:  server process (PID 2171) was terminated by signal 6: Aborted
> 2018-08-11 00:36:00.448 PDT [389][] DETAIL:  Failed process was running: insert into t (b,c) values (1,1);
> 2018-08-11 00:36:00.448 PDT [389][] LOG:  terminating any other active server processes
> 
> Below you can find the bt full showing a bunch of nested invalidations. Looking.
> 

Hmmm, it's difficult to compare "bt full" output, but my backtraces look
somewhat different (and all the backtraces I'm seeing are 100% exactly
the same). Attached for comparison.

regards

-- 
Tomas Vondra                  http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Вложения

Re: logical decoding / rewrite map vs. maxAllocatedDescs

От

Tomas Vondra

Дата:

11 августа 2018 г., 19:43:55

On 08/10/2018 11:13 PM, Andres Freund wrote:
> On 2018-08-10 22:57:57 +0200, Tomas Vondra wrote:
>>
>>
>> On 08/09/2018 07:47 PM, Alvaro Herrera wrote:
>>> On 2018-Aug-09, Tomas Vondra wrote:
>>>
>>>> I suppose there are reasons why it's done this way, and admittedly the test
>>>> that happens to trigger this is a bit extreme (essentially running pgbench
>>>> concurrently with 'vacuum full pg_class' in a loop). I'm not sure it's
>>>> extreme enough to deem it not an issue, because people using many temporary
>>>> tables often deal with bloat by doing frequent vacuum full on catalogs.
>>>
>>> Actually, it seems to me that ApplyLogicalMappingFile is just leaking
>>> the file descriptor for no good reason.  There's a different
>>> OpenTransientFile call in ReorderBufferRestoreChanges that is not
>>> intended to be closed immediately, but the other one seems a plain bug,
>>> easy enough to fix.
>>>
>>
>> Indeed. Adding a CloseTransientFile to ApplyLogicalMappingFile
>> solves the issue with hitting maxAllocatedDecs. Barring objections
>> I'll commit this shortly.
> 
> Yea, that's clearly a bug. I've not seen a patch, so I can't quite
> formally sign off, but it seems fairly obvious.
> 

I think the fix can be as simple as attached ... I'm mostly afk for the
weekend, so I'll commit & backpatch on Monday or so.

regards

-- 
Tomas Vondra                  http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Вложения

reorderbuffer-close.patch

Re: logical decoding / rewrite map vs. maxAllocatedDescs

От

Tom Lane

Дата:

11 августа 2018 г., 20:15:56

Tomas Vondra <tomas.vondra@2ndquadrant.com> writes:
>>> On 08/09/2018 07:47 PM, Alvaro Herrera wrote:
>>>> Actually, it seems to me that ApplyLogicalMappingFile is just leaking
>>>> the file descriptor for no good reason.

> I think the fix can be as simple as attached ... I'm mostly afk for the
> weekend, so I'll commit & backpatch on Monday or so.

LGTM.  While you're at it, would you fix the misspelling three lines
below this?

 * Check whether the TransactionOId 'xid' is in the pre-sorted array 'xip'.
                                ^

            regards, tom lane

Re: logical decoding / rewrite map vs. maxAllocatedDescs

От

Tomas Vondra

Дата:

11 августа 2018 г., 20:18:20

On 08/11/2018 04:15 PM, Tom Lane wrote:
> Tomas Vondra <tomas.vondra@2ndquadrant.com> writes:
>>>> On 08/09/2018 07:47 PM, Alvaro Herrera wrote:
>>>>> Actually, it seems to me that ApplyLogicalMappingFile is just leaking
>>>>> the file descriptor for no good reason.
> 
>> I think the fix can be as simple as attached ... I'm mostly afk for the
>> weekend, so I'll commit & backpatch on Monday or so.
> 
> LGTM.  While you're at it, would you fix the misspelling three lines
> below this?
> 
>  * Check whether the TransactionOId 'xid' is in the pre-sorted array 'xip'.
>                                 ^
> 

Sure.

-- 
Tomas Vondra                  http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Re: logical decoding / rewrite map vs. maxAllocatedDescs

От

Alvaro Herrera

Дата:

13 августа 2018 г., 20:46:30

On 2018-Aug-11, Tomas Vondra wrote:

> Hmmm, it's difficult to compare "bt full" output, but my backtraces look
> somewhat different (and all the backtraces I'm seeing are 100% exactly
> the same). Attached for comparison.

Hmm, looks similar enough to me -- at the bottom you have the executor
doing its thing, then an AcceptInvalidationMessages in the middle
section atop which sit a few more catalog accesses, and further up from
that you have another AcceptInvalidationMessages with more catalog
accesses.  AFAICS that's pretty much the same thing Andres was
describing.  I think the exact shape of the executor bits is not
relevant, and I suppose the exact details of what occurs when
invalidation messages are processed are not terribly important either.
I think in Andres' backtrace there are *three*
AcceptInvalidationMessages rather than two as in your case, but that
shouldn't be important either, just the fact that there are N nested
ones.

-- 
Álvaro Herrera                https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Re: logical decoding / rewrite map vs. maxAllocatedDescs

От

Andres Freund

Дата:

13 августа 2018 г., 20:49:46

Hi,

On 2018-08-13 11:46:30 -0300, Alvaro Herrera wrote:
> On 2018-Aug-11, Tomas Vondra wrote:
> 
> > Hmmm, it's difficult to compare "bt full" output, but my backtraces look
> > somewhat different (and all the backtraces I'm seeing are 100% exactly
> > the same). Attached for comparison.
> 
> Hmm, looks similar enough to me -- at the bottom you have the executor
> doing its thing, then an AcceptInvalidationMessages in the middle
> section atop which sit a few more catalog accesses, and further up from
> that you have another AcceptInvalidationMessages with more catalog
> accesses.  AFAICS that's pretty much the same thing Andres was
> describing.

It's somewhat different because it doesn't seem to involve a reload of a
nailed table, which my traces did.  I wasn't able to reproduce the crash
more than once, so I'm not at all sure how to properly verify the issue.
I'd appreciate if Thomas could try to do so again with the small patch I
provided.

Greetings,

Andres Freund

Re: logical decoding / rewrite map vs. maxAllocatedDescs

От

Alvaro Herrera

Дата:

13 августа 2018 г., 20:50:41

On 2018-Aug-11, Andres Freund wrote:

> On 2018-08-11 00:46:25 -0700, Andres Freund wrote:
> > Below you can find the bt full showing a bunch of nested invalidations. Looking.
> 
> Hm. I wonder if the attached fixes the issue for you.  If it's this I
> don't understand why this doesn't occur on older branches...
> 
> I've not yet been able to reliably reproduce the issue without the
> patch, so I'm not sure it means much that it didn't reoccur afterwards.

Well, the line you're patching was introduced in 2ce64caaf793 (looking
at pg10), and was not replacing a line with the exact same mistake.

-- 
Álvaro Herrera                https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Re: logical decoding / rewrite map vs. maxAllocatedDescs

От

Andres Freund

Дата:

13 августа 2018 г., 20:54:05

On 2018-08-13 11:50:41 -0300, Alvaro Herrera wrote:
> On 2018-Aug-11, Andres Freund wrote:
> 
> > On 2018-08-11 00:46:25 -0700, Andres Freund wrote:
> > > Below you can find the bt full showing a bunch of nested invalidations. Looking.
> > 
> > Hm. I wonder if the attached fixes the issue for you.  If it's this I
> > don't understand why this doesn't occur on older branches...
> > 
> > I've not yet been able to reliably reproduce the issue without the
> > patch, so I'm not sure it means much that it didn't reoccur afterwards.
> 
> Well, the line you're patching was introduced in 2ce64caaf793 (looking
> at pg10), and was not replacing a line with the exact same mistake.

I'm not clear on what you're trying to say?  My problem is that Thomas'
backtraces don't show involvement by that function, which makes it less
likely that it matters, no?

Greetings,

Andres Freund

Re: logical decoding / rewrite map vs. maxAllocatedDescs

От

Tomas Vondra

Дата:

14 августа 2018 г., 17:49:03

On 08/13/2018 04:49 PM, Andres Freund wrote:
> Hi,
> 
> On 2018-08-13 11:46:30 -0300, Alvaro Herrera wrote:
>> On 2018-Aug-11, Tomas Vondra wrote:
>>
>>> Hmmm, it's difficult to compare "bt full" output, but my backtraces look
>>> somewhat different (and all the backtraces I'm seeing are 100% exactly
>>> the same). Attached for comparison.
>>
>> Hmm, looks similar enough to me -- at the bottom you have the executor
>> doing its thing, then an AcceptInvalidationMessages in the middle
>> section atop which sit a few more catalog accesses, and further up from
>> that you have another AcceptInvalidationMessages with more catalog
>> accesses.  AFAICS that's pretty much the same thing Andres was
>> describing.
> 
> It's somewhat different because it doesn't seem to involve a reload of a
> nailed table, which my traces did.  I wasn't able to reproduce the crash
> more than once, so I'm not at all sure how to properly verify the issue.
> I'd appreciate if Thomas could try to do so again with the small patch I
> provided.
> 

I'll try in the evening. I've tried reproducing it on my laptop, but I 
can't make that happen for some reason - I know I've seen some crashes 
here, but all the reproducers were from the workstation I have at home.

I wonder if there's some subtle difference between the two boxes, making 
it more likely on one of them ... the whole environment (distribution, 
packages, compiler, ...) should be exactly the same, though. The only 
thing I can think of is different CPU speed, possibly making some race 
conditions more/less likely. No idea.

regards

-- 
Tomas Vondra                  http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Re: logical decoding / rewrite map vs. maxAllocatedDescs

От

Tomas Vondra

Дата:

14 августа 2018 г., 20:05:29

On 08/14/2018 01:49 PM, Tomas Vondra wrote:
> On 08/13/2018 04:49 PM, Andres Freund wrote:
>> Hi,
>>
>> On 2018-08-13 11:46:30 -0300, Alvaro Herrera wrote:
>>> On 2018-Aug-11, Tomas Vondra wrote:
>>>
>>>> Hmmm, it's difficult to compare "bt full" output, but my backtraces 
>>>> look
>>>> somewhat different (and all the backtraces I'm seeing are 100% exactly
>>>> the same). Attached for comparison.
>>>
>>> Hmm, looks similar enough to me -- at the bottom you have the executor
>>> doing its thing, then an AcceptInvalidationMessages in the middle
>>> section atop which sit a few more catalog accesses, and further up from
>>> that you have another AcceptInvalidationMessages with more catalog
>>> accesses.  AFAICS that's pretty much the same thing Andres was
>>> describing.
>>
>> It's somewhat different because it doesn't seem to involve a reload of a
>> nailed table, which my traces did.  I wasn't able to reproduce the crash
>> more than once, so I'm not at all sure how to properly verify the issue.
>> I'd appreciate if Thomas could try to do so again with the small patch I
>> provided.
>>
> 
> I'll try in the evening. I've tried reproducing it on my laptop, but I 
> can't make that happen for some reason - I know I've seen some crashes 
> here, but all the reproducers were from the workstation I have at home.
> 
> I wonder if there's some subtle difference between the two boxes, making 
> it more likely on one of them ... the whole environment (distribution, 
> packages, compiler, ...) should be exactly the same, though. The only 
> thing I can think of is different CPU speed, possibly making some race 
> conditions more/less likely. No idea.
> 

I take that back - I can reproduce the crashes, both with and without 
the patch, all the way back to 9.6. Attached is a bunch of backtraces 
from various versions. There's a bit of variability depending on which 
pgbench script gets started first (insert.sql or vacuum.sql) - in one 
case (when vacuum is started before insert) the crash happens in 
InitPostgres/RelationCacheInitializePhase3, otherwise it happens in 
exec_simple_query.

Another observation is that the failing COPY is not necessary, I can 
reproduce the crashes without this (so even with wal_level=replica).

regards

-- 
Tomas Vondra                  http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Вложения

Re: logical decoding / rewrite map vs. maxAllocatedDescs

От

Tomas Vondra

Дата:

15 августа 2018 г., 03:26:30


On 8/14/18 10:05 AM, Tomas Vondra wrote:
> ...
 >
> I take that back - I can reproduce the crashes, both with and without 
> the patch, all the way back to 9.6. Attached is a bunch of backtraces 
> from various versions. There's a bit of variability depending on which 
> pgbench script gets started first (insert.sql or vacuum.sql) - in one 
> case (when vacuum is started before insert) the crash happens in 
> InitPostgres/RelationCacheInitializePhase3, otherwise it happens in 
> exec_simple_query.
> 
> Another observation is that the failing COPY is not necessary, I can 
> reproduce the crashes without this (so even with wal_level=replica).
>

BTW I have managed to reproduce this on an old test server. If anyone 
wants to take a look, I can arrange ssh access to that machine (for 
trustworthy developers). Let me know.

regards

-- 
Tomas Vondra                  http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Re: logical decoding / rewrite map vs. maxAllocatedDescs

От

Tomas Vondra

Дата:

16 августа 2018 г., 21:07:17

On 08/11/2018 04:18 PM, Tomas Vondra wrote:
> On 08/11/2018 04:15 PM, Tom Lane wrote:
>> Tomas Vondra <tomas.vondra@2ndquadrant.com> writes:
>>>>> On 08/09/2018 07:47 PM, Alvaro Herrera wrote:
>>>>>> Actually, it seems to me that ApplyLogicalMappingFile is just leaking
>>>>>> the file descriptor for no good reason.
>>
>>> I think the fix can be as simple as attached ... I'm mostly afk for the
>>> weekend, so I'll commit & backpatch on Monday or so.
>>
>> LGTM.  While you're at it, would you fix the misspelling three lines
>> below this?
>>
>>  * Check whether the TransactionOId 'xid' is in the pre-sorted array 'xip'.
>>                                 ^
> 
> Sure.
> 

I've pushed this, and backpatched it all the way back to 9.4 where
logical decoding was introduced.

While this resolves the way to run out of file descriptors, I wonder if
there are other trivial ways to trigger it (say, long-running
transaction spanning many 'vacuum full pg_class' runs). Not sure, will
try later.

The other question is whether errors are handled correctly - as reported
initially, I've seen this to trigger

ERROR:  XX000: subtransaction logged without previous top-level txn record

I assume just fixing the error did not really fix that, so that if
something else fails we might end up in the same state.

regards

-- 
Tomas Vondra                  http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Вход в личный кабинет

Восстановление пароля

Подтверждение аккаунта

Изменение пароля

Обсуждение: logical decoding / rewrite map vs. maxAllocatedDescs

Вложения

Вложения

Вложения

Вложения

Вложения

Вложения