logical decoding / rewrite map vs. maxAllocatedDescs

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

Tomas Vondra <tomas(dot)vondra(at)2ndquadrant(dot)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

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

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

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

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

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

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

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

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

On Sat, Aug 11, 2018 at 12:06 AM, Andres Freund <andres(at)anarazel(dot)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

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

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 8192 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.

#0 __GI_raise (sig=sig(at)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(at)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

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

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

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 of 8192 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

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

Tomas Vondra <tomas(dot)vondra(at)2ndquadrant(dot)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

On 08/11/2018 04:15 PM, Tom Lane wrote:
> Tomas Vondra <tomas(dot)vondra(at)2ndquadrant(dot)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

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

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

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

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

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

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

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

On 08/11/2018 04:18 PM, Tomas Vondra wrote:
> On 08/11/2018 04:15 PM, Tom Lane wrote:
>> Tomas Vondra <tomas(dot)vondra(at)2ndquadrant(dot)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