Thread
Commits
-
Close the file descriptor in ApplyLogicalMappingFile
- 43ba5ac6aa48 11.0 landed
- e00f4b68dc87 10.6 landed
- 5257b9bfbafd 9.6.11 landed
- 864ecd716a0d 9.5.15 landed
- ef1ac5b2ad08 9.4.20 landed
- fa73b377ee11 12.0 landed
-
logical decoding / rewrite map vs. maxAllocatedDescs
Tomas Vondra <tomas.vondra@2ndquadrant.com> — 2018-08-09T17:31:00Z
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 -
Re: logical decoding / rewrite map vs. maxAllocatedDescs
Tom Lane <tgl@sss.pgh.pa.us> — 2018-08-09T17:42:17Z
Tomas Vondra <tomas.vondra@2ndquadrant.com> writes: > While investigating an issue with rewrite maps in logical decoding, I > found it's pretty darn trivial to hit this: > ERROR: 53000: exceeded maxAllocatedDescs (492) while trying to open > file "pg_logical/mappings/map-4000-4eb-1_60DE1E08-5376b5-537c6b" > This happens because we seem to open the mapping files and keep them > open until the next checkpoint, at which point we fsync + close. It sounds like whoever wrote that code was completely impervious to the API spec for AllocateFile(): * Note that files that will be open for any significant length of time * should NOT be handled this way, since they cannot share kernel file * descriptors with other files; there is grave risk of running out of FDs * if anyone locks down too many FDs. Perhaps these files should be accessed through fd.c's VFD infrastructure rather than ignoring it. Reinventing it is especially not the way to go. > Furthermore, the situation is made worse by opening the same file > repeatedly, under different file descriptor. That's just stupid :-( Note that the limit on maxAllocatedDescs is based on the kernel limit on how many files a process can have open, so assuming you can increase it is not going to end well. regards, tom lane
-
Re: logical decoding / rewrite map vs. maxAllocatedDescs
Alvaro Herrera <alvherre@2ndquadrant.com> — 2018-08-09T17:47:46Z
On 2018-Aug-09, Tomas Vondra wrote: > I suppose there are reasons why it's done this way, and admittedly the test > that happens to trigger this is a bit extreme (essentially running pgbench > concurrently with 'vacuum full pg_class' in a loop). I'm not sure it's > extreme enough to deem it not an issue, because people using many temporary > tables often deal with bloat by doing frequent vacuum full on catalogs. Actually, it seems to me that ApplyLogicalMappingFile is just leaking the file descriptor for no good reason. There's a different OpenTransientFile call in ReorderBufferRestoreChanges that is not intended to be closed immediately, but the other one seems a plain bug, easy enough to fix. > But wait, there's more - what happens after hitting the limit? We restart > the decoding process, and end up getting this: > > ERROR: 53000: exceeded maxAllocatedDescs (492) while trying to open > file "pg_logical/mappings/map-4000-4eb-1_60DE1E08-5376b5-537c6b" > LOCATION: OpenTransientFile, fd.c:2161 > LOG: 00000: starting logical decoding for slot "s" > DETAIL: streaming transactions committing after 1/6097DD48, reading > WAL from 1/60275848 > LOCATION: CreateDecodingContext, logical.c:414 > LOG: 00000: logical decoding found consistent point at 1/60275848 > DETAIL: Logical decoding will begin using saved snapshot. > LOCATION: SnapBuildRestore, snapbuild.c:1872 > ERROR: XX000: subtransaction logged without previous top-level txn > record Hmm, I wonder if we introduced some bug in f49a80c481f7. > I'd say this implies the "can't open file" is handled in a way that corrupts > the mapping files, making it impossible to restart the decoding. AFAICS the > only option at this point is to drop the subscription and start over. Wow, that seems pretty serious. Clearly that's a different bug that must be fixed. -- Álvaro Herrera https://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
-
Re: logical decoding / rewrite map vs. maxAllocatedDescs
Alvaro Herrera <alvherre@2ndquadrant.com> — 2018-08-09T17:58:46Z
On 2018-Aug-09, Tom Lane wrote: > It sounds like whoever wrote that code was completely impervious to the > API spec for AllocateFile(): > > * Note that files that will be open for any significant length of time > * should NOT be handled this way, since they cannot share kernel file > * descriptors with other files; there is grave risk of running out of FDs > * if anyone locks down too many FDs. > > Perhaps these files should be accessed through fd.c's VFD infrastructure > rather than ignoring it. Reinventing it is especially not the way to go. Ah, right. Maybe ReorderBufferRestoreChanges should use PathNameOpenFile / FileRead ... -- Álvaro Herrera https://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
-
Re: logical decoding / rewrite map vs. maxAllocatedDescs
Tomas Vondra <tomas.vondra@2ndquadrant.com> — 2018-08-09T17:58:57Z
On 08/09/2018 07:47 PM, Alvaro Herrera wrote: > On 2018-Aug-09, Tomas Vondra wrote: > >> I suppose there are reasons why it's done this way, and admittedly the test >> that happens to trigger this is a bit extreme (essentially running pgbench >> concurrently with 'vacuum full pg_class' in a loop). I'm not sure it's >> extreme enough to deem it not an issue, because people using many temporary >> tables often deal with bloat by doing frequent vacuum full on catalogs. > > Actually, it seems to me that ApplyLogicalMappingFile is just leaking > the file descriptor for no good reason. There's a different > OpenTransientFile call in ReorderBufferRestoreChanges that is not > intended to be closed immediately, but the other one seems a plain bug, > easy enough to fix. > >> But wait, there's more - what happens after hitting the limit? We restart >> the decoding process, and end up getting this: >> >> ERROR: 53000: exceeded maxAllocatedDescs (492) while trying to open >> file "pg_logical/mappings/map-4000-4eb-1_60DE1E08-5376b5-537c6b" >> LOCATION: OpenTransientFile, fd.c:2161 >> LOG: 00000: starting logical decoding for slot "s" >> DETAIL: streaming transactions committing after 1/6097DD48, reading >> WAL from 1/60275848 >> LOCATION: CreateDecodingContext, logical.c:414 >> LOG: 00000: logical decoding found consistent point at 1/60275848 >> DETAIL: Logical decoding will begin using saved snapshot. >> LOCATION: SnapBuildRestore, snapbuild.c:1872 >> ERROR: XX000: subtransaction logged without previous top-level txn >> record > > Hmm, I wonder if we introduced some bug in f49a80c481f7. > That's possible. I'm running on f85537a88d, i.e. with f49a80c481f7. >> I'd say this implies the "can't open file" is handled in a way that corrupts >> the mapping files, making it impossible to restart the decoding. AFAICS the >> only option at this point is to drop the subscription and start over. > > Wow, that seems pretty serious. Clearly that's a different bug that > must be fixed. > Yep. regards -- Tomas Vondra http://www.2ndQuadrant.com PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
-
Re: logical decoding / rewrite map vs. maxAllocatedDescs
Tomas Vondra <tomas.vondra@2ndquadrant.com> — 2018-08-10T20:57:57Z
On 08/09/2018 07:47 PM, Alvaro Herrera wrote: > On 2018-Aug-09, Tomas Vondra wrote: > >> I suppose there are reasons why it's done this way, and admittedly the test >> that happens to trigger this is a bit extreme (essentially running pgbench >> concurrently with 'vacuum full pg_class' in a loop). I'm not sure it's >> extreme enough to deem it not an issue, because people using many temporary >> tables often deal with bloat by doing frequent vacuum full on catalogs. > > Actually, it seems to me that ApplyLogicalMappingFile is just leaking > the file descriptor for no good reason. There's a different > OpenTransientFile call in ReorderBufferRestoreChanges that is not > intended to be closed immediately, but the other one seems a plain bug, > easy enough to fix. > Indeed. Adding a CloseTransientFile to ApplyLogicalMappingFile solves the issue with hitting maxAllocatedDecs. Barring objections I'll commit this shortly. >> But wait, there's more - what happens after hitting the limit? We restart >> the decoding process, and end up getting this: >> >> ERROR: 53000: exceeded maxAllocatedDescs (492) while trying to open >> file "pg_logical/mappings/map-4000-4eb-1_60DE1E08-5376b5-537c6b" >> LOCATION: OpenTransientFile, fd.c:2161 >> LOG: 00000: starting logical decoding for slot "s" >> DETAIL: streaming transactions committing after 1/6097DD48, reading >> WAL from 1/60275848 >> LOCATION: CreateDecodingContext, logical.c:414 >> LOG: 00000: logical decoding found consistent point at 1/60275848 >> DETAIL: Logical decoding will begin using saved snapshot. >> LOCATION: SnapBuildRestore, snapbuild.c:1872 >> ERROR: XX000: subtransaction logged without previous top-level txn >> record > > Hmm, I wonder if we introduced some bug in f49a80c481f7. > Not sure. I've tried reproducing it both on b767b3f2e5b7 (that's f49... in REL_10_STABLE branch) and 09879f7536350 (that's the commit immediately before it), and I can't reproduce it for some reason. I'll try on Monday on the same laptop I used before (it's in the office, so I can't try now). But while running the tests on this machine, I repeatedly got pgbench failures like this: client 2 aborted in command 0 of script 0; ERROR: could not read block 3 in file "base/16384/24573": read only 0 of 8192 bytes That kinda reminds me the issues we're observing on some buildfarm machines, I wonder if it's the same thing. I suppose relfilenode 24573 is pg_class, which is the only table I'm running vacuum full on here. regards -- Tomas Vondra http://www.2ndQuadrant.com PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
-
Re: logical decoding / rewrite map vs. maxAllocatedDescs
Andres Freund <andres@anarazel.de> — 2018-08-10T21:13:40Z
On 2018-08-10 22:57:57 +0200, Tomas Vondra wrote: > > > On 08/09/2018 07:47 PM, Alvaro Herrera wrote: > > On 2018-Aug-09, Tomas Vondra wrote: > > > >> I suppose there are reasons why it's done this way, and admittedly the test > >> that happens to trigger this is a bit extreme (essentially running pgbench > >> concurrently with 'vacuum full pg_class' in a loop). I'm not sure it's > >> extreme enough to deem it not an issue, because people using many temporary > >> tables often deal with bloat by doing frequent vacuum full on catalogs. > > > > Actually, it seems to me that ApplyLogicalMappingFile is just leaking > > the file descriptor for no good reason. There's a different > > OpenTransientFile call in ReorderBufferRestoreChanges that is not > > intended to be closed immediately, but the other one seems a plain bug, > > easy enough to fix. > > > > Indeed. Adding a CloseTransientFile to ApplyLogicalMappingFile solves > the issue with hitting maxAllocatedDecs. Barring objections I'll commit > this shortly. Yea, that's clearly a bug. I've not seen a patch, so I can't quite formally sign off, but it seems fairly obvious. > But while running the tests on this machine, I repeatedly got pgbench > failures like this: > > client 2 aborted in command 0 of script 0; ERROR: could not read block > 3 in file "base/16384/24573": read only 0 of 8192 bytes > > That kinda reminds me the issues we're observing on some buildfarm > machines, I wonder if it's the same thing. Oooh, that's interesting! What's the precise recipe that gets you there? Greetings, Andres Freund
-
Re: logical decoding / rewrite map vs. maxAllocatedDescs
Tomas Vondra <tomas.vondra@2ndquadrant.com> — 2018-08-10T21:59:44Z
On 08/10/2018 11:13 PM, Andres Freund wrote: > On 2018-08-10 22:57:57 +0200, Tomas Vondra wrote: >> >> >> On 08/09/2018 07:47 PM, Alvaro Herrera wrote: >>> On 2018-Aug-09, Tomas Vondra wrote: >>> >>>> I suppose there are reasons why it's done this way, and admittedly the test >>>> that happens to trigger this is a bit extreme (essentially running pgbench >>>> concurrently with 'vacuum full pg_class' in a loop). I'm not sure it's >>>> extreme enough to deem it not an issue, because people using many temporary >>>> tables often deal with bloat by doing frequent vacuum full on catalogs. >>> >>> Actually, it seems to me that ApplyLogicalMappingFile is just leaking >>> the file descriptor for no good reason. There's a different >>> OpenTransientFile call in ReorderBufferRestoreChanges that is not >>> intended to be closed immediately, but the other one seems a plain bug, >>> easy enough to fix. >>> >> >> Indeed. Adding a CloseTransientFile to ApplyLogicalMappingFile solves >> the issue with hitting maxAllocatedDecs. Barring objections I'll commit >> this shortly. > > Yea, that's clearly a bug. I've not seen a patch, so I can't quite > formally sign off, but it seems fairly obvious. > > >> But while running the tests on this machine, I repeatedly got pgbench >> failures like this: >> >> client 2 aborted in command 0 of script 0; ERROR: could not read block >> 3 in file "base/16384/24573": read only 0 of 8192 bytes >> >> That kinda reminds me the issues we're observing on some buildfarm >> machines, I wonder if it's the same thing. > > Oooh, that's interesting! What's the precise recipe that gets you there? > I don't have an exact reproducer - it's kinda rare and unpredictable, and I'm not sure how much it depends on the environment etc. But I'm doing this: 1) one cluster with publication (wal_level=logical) 2) one cluster with subscription to (1) 3) simple table, replicated from (1) to (2) -- publisher create table t (a serial primary key, b int, c int); create publication p for table t; -- subscriber create table t (a serial primary key, b int, c int); create subscription s CONNECTION '...' publication p; 4) pgbench inserting rows into the replicated table pgbench -n -c 4 -T 300 -p 5433 -f insert.sql test 5) pgbench doing vacuum full on pg_class pgbench -n -f vacuum.sql -T 300 -p 5433 test And once in a while I see failures like this: client 0 aborted in command 0 of script 0; ERROR: could not read block 3 in file "base/16384/86242": read only 0 of 8192 bytes client 3 aborted in command 0 of script 0; ERROR: could not read block 3 in file "base/16384/86242": read only 0 of 8192 bytes client 2 aborted in command 0 of script 0; ERROR: could not read block 3 in file "base/16384/86242": read only 0 of 8192 bytes or this: client 2 aborted in command 0 of script 0; ERROR: could not read block 3 in file "base/16384/89369": read only 0 of 8192 bytes client 1 aborted in command 0 of script 0; ERROR: could not read block 3 in file "base/16384/89369": read only 0 of 8192 bytes I suspect there's some other ingredient, e.g. some manipulation with the subscription. Or maybe it's not needed at all and I'm just imagining things. regards -- Tomas Vondra http://www.2ndQuadrant.com PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
-
Re: logical decoding / rewrite map vs. maxAllocatedDescs
Tomas Vondra <tomas.vondra@2ndquadrant.com> — 2018-08-10T23:55:43Z
On 08/10/2018 11:59 PM, Tomas Vondra wrote: > > ... > > I suspect there's some other ingredient, e.g. some manipulation with the > subscription. Or maybe it's not needed at all and I'm just imagining things. > Indeed, the manipulation with the subscription seems to be the key here. I pretty reliably get the 'could not read block' error when doing this: 1) start the insert pgbench pgbench -n -c 4 -T 300 -p 5433 -f insert.sql test 2) start the vacuum full pgbench pgbench -n -f vacuum.sql -T 300 -p 5433 test 3) try to create a subscription, but with small amount of conflicting data so that the sync fails like this: LOG: logical replication table synchronization worker for subscription "s", table "t" has started ERROR: duplicate key value violates unique constraint "t_pkey" DETAIL: Key (a)=(5997542) already exists. CONTEXT: COPY t, line 1 LOG: worker process: logical replication worker for subscription 16458 sync 16397 (PID 31983) exited with exit code 1 4) At this point the insert pgbench (at least some clients) should have failed with the error. If not, rinse and repeat. This kinda explains why I've been seeing the error only occasionally, because it only happened when I forgotten to clean the table on the subscriber while recreating the subscription. regards -- Tomas Vondra http://www.2ndQuadrant.com PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
-
Re: logical decoding / rewrite map vs. maxAllocatedDescs
Andres Freund <andres@anarazel.de> — 2018-08-11T07:06:18Z
Hi, On 2018-08-11 01:55:43 +0200, Tomas Vondra wrote: > On 08/10/2018 11:59 PM, Tomas Vondra wrote: > > > > ... > > > > I suspect there's some other ingredient, e.g. some manipulation with the > > subscription. Or maybe it's not needed at all and I'm just imagining things. > > > > Indeed, the manipulation with the subscription seems to be the key here. > I pretty reliably get the 'could not read block' error when doing this: > > 1) start the insert pgbench > > pgbench -n -c 4 -T 300 -p 5433 -f insert.sql test > > 2) start the vacuum full pgbench > > pgbench -n -f vacuum.sql -T 300 -p 5433 test > > 3) try to create a subscription, but with small amount of conflicting > data so that the sync fails like this: > > LOG: logical replication table synchronization worker for > subscription "s", table "t" has started > ERROR: duplicate key value violates unique constraint "t_pkey" > DETAIL: Key (a)=(5997542) already exists. > CONTEXT: COPY t, line 1 > LOG: worker process: logical replication worker for subscription > 16458 sync 16397 (PID 31983) exited with exit code 1 > > 4) At this point the insert pgbench (at least some clients) should have > failed with the error. If not, rinse and repeat. > > This kinda explains why I've been seeing the error only occasionally, > because it only happened when I forgotten to clean the table on the > subscriber while recreating the subscription. I'll try to reproduce this. If you're also looking, I suspect a good first hint would be to just change the ERROR into a PANIC and look at the backtrace from the generated core file. To the point that I wonder if we shouldn't just change the ERROR into a PANIC on master (but not REL_11_STABLE), so the buildfarm gives us feedback. I don't think the problem can fundamentally be related to subscriptions, given the error occurs before any subscriptions are created in the schedule. Greetings, Andres Freund
-
Re: logical decoding / rewrite map vs. maxAllocatedDescs
Peter Geoghegan <pg@bowt.ie> — 2018-08-11T07:15:25Z
On Sat, Aug 11, 2018 at 12:06 AM, Andres Freund <andres@anarazel.de> wrote: > To the point that I wonder if we shouldn't just change the ERROR into a > PANIC on master (but not REL_11_STABLE), so the buildfarm gives us > feedback. I don't think the problem can fundamentally be related to > subscriptions, given the error occurs before any subscriptions are > created in the schedule. +1. I like that idea. -- Peter Geoghegan
-
Re: logical decoding / rewrite map vs. maxAllocatedDescs
Andres Freund <andres@anarazel.de> — 2018-08-11T07:34:15Z
Hi, On 2018-08-11 01:55:43 +0200, Tomas Vondra wrote: > On 08/10/2018 11:59 PM, Tomas Vondra wrote: > > > > ... > > > > I suspect there's some other ingredient, e.g. some manipulation with the > > subscription. Or maybe it's not needed at all and I'm just imagining things. > > > > Indeed, the manipulation with the subscription seems to be the key here. > I pretty reliably get the 'could not read block' error when doing this: > > 1) start the insert pgbench > > pgbench -n -c 4 -T 300 -p 5433 -f insert.sql test > > 2) start the vacuum full pgbench > > pgbench -n -f vacuum.sql -T 300 -p 5433 test Just to be clear: 5433 is the subscriber, right? I tried it with both, but it's not clear what you meant with either the previous or the this email. > 3) try to create a subscription, but with small amount of conflicting > data so that the sync fails like this: > > LOG: logical replication table synchronization worker for > subscription "s", table "t" has started > ERROR: duplicate key value violates unique constraint "t_pkey" > DETAIL: Key (a)=(5997542) already exists. > CONTEXT: COPY t, line 1 > LOG: worker process: logical replication worker for subscription > 16458 sync 16397 (PID 31983) exited with exit code 1 > > 4) At this point the insert pgbench (at least some clients) should have > failed with the error. If not, rinse and repeat. I've run this numerous times now, and I haven't triggered it yet :/ Greetings, Andres Freund
-
Re: logical decoding / rewrite map vs. maxAllocatedDescs
Andres Freund <andres@anarazel.de> — 2018-08-11T07:46:25Z
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@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51 set = {__val = {0, 14583431671641719254, 0, 0, 0, 0, 0, 0, 0, 0, 1296236544, 94518929497176, 1024, 0, 0, 0}} pid = <optimized out> tid = <optimized out> ret = <optimized out> #1 0x00007f0de57f52f1 in __GI_abort () at abort.c:79 save_stage = 1 act = {__sigaction_handler = {sa_handler = 0x0, sa_sigaction = 0x0}, sa_mask = {__val = {0, 0, 0, 17399330032, 94518929499360, 94518929499336, 94518929496896, 140720527947024, 94518900188034, 69, 94518929499360, 4870, 94518929496896, 94518929499360, 139697663207040, 139697663189664}}, sa_flags = -444414227, sa_restorer = 0x0} sigs = {__val = {32, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0}} #2 0x000055f6e5748e0b in errfinish (dummy=0) at /home/andres/src/postgresql/src/backend/utils/error/elog.c:557 edata = 0x55f6e5af6dc0 <errordata> elevel = 22 oldcontext = 0x55f6e743c570 econtext = 0x0 __func__ = "errfinish" #3 0x000055f6e55d2c0c in mdread (reln=0x55f6e7415de0, forknum=MAIN_FORKNUM, blocknum=3, buffer=0x7f0de4eb5700 "\001") at /home/andres/src/postgresql/src/backend/storage/smgr/md.c:786 seekpos = 24576 nbytes = 0 v = 0x55f6e73a1448 __func__ = "mdread" #4 0x000055f6e55d5554 in smgrread (reln=0x55f6e7415de0, forknum=MAIN_FORKNUM, blocknum=3, buffer=0x7f0de4eb5700 "\001") at /home/andres/src/postgresql/src/backend/storage/smgr/smgr.c:628 No locals. #5 0x000055f6e5593bea in ReadBuffer_common (smgr=0x55f6e7415de0, relpersistence=112 'p', forkNum=MAIN_FORKNUM, blockNum=3, mode=RBM_NORMAL, strategy=0x0, hit=0x7ffc0d14b7fb) at /home/andres/src/postgresql/src/backend/storage/buffer/bufmgr.c:890 io_start = {tv_sec = 140720527947552, tv_nsec = 94518898352892} io_time = {tv_sec = 72057594257389344, tv_nsec = 72197288386101248} bufHdr = 0x7f0de3eb76c0 bufBlock = 0x7f0de4eb5700 found = false isExtend = false isLocalBuf = false __func__ = "ReadBuffer_common" #6 0x000055f6e55934fb in ReadBufferExtended (reln=0x7f0de627a850, forkNum=MAIN_FORKNUM, blockNum=3, mode=RBM_NORMAL, strategy=0x0) at /home/andres/src/postgresql/src/backend/storage/buffer/bufmgr.c:664 hit = false buf = 1980 __func__ = "ReadBufferExtended" #7 0x000055f6e55933cf in ReadBuffer (reln=0x7f0de627a850, blockNum=3) at /home/andres/src/postgresql/src/backend/storage/buffer/bufmgr.c:596 No locals. #8 0x000055f6e520a530 in _bt_getbuf (rel=0x7f0de627a850, blkno=3, access=1) at /home/andres/src/postgresql/src/backend/access/nbtree/nbtpage.c:736 buf = 22006 __func__ = "_bt_getbuf" #9 0x000055f6e52091cf in _bt_getroot (rel=0x7f0de627a850, access=1) at /home/andres/src/postgresql/src/backend/access/nbtree/nbtpage.c:282 metabuf = 0 metapg = 0x55f6e5216574 <_bt_preprocess_keys+326> "\351\371\004" metaopaque = 0x7ffc0d14b9b0 rootbuf = 22006 rootpage = 0x7ffc0d14b954 "" rootopaque = 0x55f6e743c6b0 rootblkno = 3 rootlevel = 1 metad = 0x55f6e741da88 __func__ = "_bt_getroot" #10 0x000055f6e5210ea0 in _bt_search (rel=0x7f0de627a850, keysz=1, scankey=0x7ffc0d14c2e0, nextkey=false, bufP=0x7ffc0d14cce4, access=1, snapshot=0x55f6e5aade80 <CatalogSnapshotData>) at /home/andres/src/postgresql/src/backend/access/nbtree/nbtsearch.c:104 stack_in = 0x0 page_access = 1 #11 0x000055f6e521263d in _bt_first (scan=0x55f6e743c6b0, dir=ForwardScanDirection) at /home/andres/src/postgresql/src/backend/access/nbtree/nbtsearch.c:1060 rel = 0x7f0de627a850 so = 0x55f6e74405d0 buf = 0 stack = 0x7ffc0d14cd20 offnum = 0 strat = 3 nextkey = false goback = false startKeys = {0x55f6e743c8b8, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x7ffc0d14cd00, 0x4e55b8917, 0x55f6e743c808, 0x80, 0x0, 0x0, 0x0, 0x400001d68, 0x55f6e743c8a0, 0x80, 0x55f6e743c570, 0x55f6e5785cb2 <palloc+262>, 0x0, 0x1cd0, 0x20d8, 0x55f6e743c648, 0x7ffc0d14cd20, 0x55f6e5785cb2 <palloc+262>, 0x0, 0x48, 0x1305, 0x55f6e743c570, 0x55f6e743c8b8, 0x48} scankeys = {{sk_flags = 196608, sk_attno = 1, sk_strategy = 0, sk_subtype = 0, sk_collation = 100, sk_func = {fn_addr = 0x55f6e52029ed <btoidcmp>, fn_oid = 356, fn_nargs = 2, fn_strict = true, fn_retset = false, fn_stats = 2 '\002', fn_extra = 0x0, fn_mcxt = 0x55f6e743c570, fn_expr = 0x0}, sk_argument = 1259}, {sk_flags = 0, sk_attno = 0, sk_strategy = 0, sk_subtype = 0, sk_collation = 0, sk_func = {fn_addr = 0x0, fn_oid = 1296236544, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 88 'X', fn_extra = 0x1, fn_mcxt = 0x0, fn_expr = 0x0}, sk_argument = 0}, {sk_flags = 0, sk_attno = 0, sk_strategy = 0, sk_subtype = 0, sk_collation = 0, sk_func = {fn_addr = 0x0, fn_oid = 3879362648, fn_nargs = 22006, fn_strict = false, fn_retset = false, fn_stats = 0 '\000', fn_extra = 0x55f6e5779cb6 <AllocSetAlloc+2370>, fn_mcxt = 0x18, fn_expr = 0x55f6e737d320}, sk_argument = 16777240}, {sk_flags = 0, sk_attno = 0, sk_strategy = 0, sk_subtype = 0, sk_collation = 0, sk_func = {fn_addr = 0x0, fn_oid = 1296236544, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 64 '@', fn_extra = 0x8, fn_mcxt = 0x0, fn_expr = 0x0}, sk_argument = 0}, {sk_flags = 1296236544, sk_attno = 0, sk_strategy = 0, sk_subtype = 3879979280, sk_collation = 22006, sk_func = {fn_addr = 0x0, fn_oid = 0, fn_nargs = 1, fn_strict = false, fn_retset = 32, fn_stats = 148 '\224', fn_extra = 0x7f0de4c9f700, fn_mcxt = 0x7ffc0d14c480, fn_expr = 0x55f6e5218baa <_bt_check_natts+72>}, sk_argument = 140720527950960}, {sk_flags = -446938903, sk_attno = 1, sk_strategy = 0, sk_subtype = 24, sk_collation = 0, sk_func = {fn_addr = 0x55f6e577882e <wipe_mem+126>, fn_oid = 32, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 40 '(', fn_extra = 0x4d430001, fn_mcxt = 0x55f6e743c928, fn_expr = 0x20}, sk_argument = 0}, {sk_flags = 0, sk_attno = 0, sk_strategy = 0, sk_subtype = 0, sk_collation = 0, sk_func = {fn_addr = 0x4d430000, fn_oid = 3879979304, fn_nargs = 22006, fn_strict = false, fn_retset = false, fn_stats = 32 ' ', fn_extra = 0x0, fn_mcxt = 0x0, fn_expr = 0x0}, sk_argument = 1296236545}, {sk_flags = -415604696, sk_attno = 22006, sk_strategy = 0, sk_subtype = 24, sk_collation = 0, sk_func = {fn_addr = 0x0, fn_oid = 0, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 0 '\000', fn_extra = 0x4d430000, fn_mcxt = 0x55f6e73a6058, fn_expr = 0x8}, sk_argument = 0}, {sk_flags = 0, sk_attno = 0, sk_strategy = 0, sk_subtype = 0, sk_collation = 0, sk_func = {fn_addr = 0x4d430000, fn_oid = 3879362600, fn_nargs = 22006, fn_strict = false, fn_retset = false, fn_stats = 16 '\020', fn_extra = 0x0, fn_mcxt = 0x0, fn_expr = 0x55f6e599bce0}, sk_argument = 140720527952640}, {sk_flags = 219466880, sk_attno = 32764, sk_strategy = 0, sk_subtype = 11, sk_collation = 0, sk_func = {fn_addr = 0x7ffc0d14cb10, fn_oid = 15, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 20 '\024', fn_extra = 0x8314000100000001, fn_mcxt = 0x8314000000212ded, fn_expr = 0x55f6e5ad2cb0 <PrivateRefCountArray+16>}, sk_argument = 3847846476}, {sk_flags = 0, sk_attno = 0, sk_strategy = 0, sk_subtype = 3847845018, sk_collation = 2, sk_func = {fn_addr = 0xffffffffffffffff, fn_oid = 2, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 32 ' ', fn_extra = 0x55f600000000, fn_mcxt = 0x0, fn_expr = 0x0}, sk_argument = 140720308486144}, {sk_flags = 219465440, sk_attno = 32764, sk_strategy = 0, sk_subtype = 0, sk_collation = 32764, sk_func = {fn_addr = 0x55f6fffffff1, fn_oid = 0, fn_nargs = 32764, fn_strict = false, fn_retset = false, fn_stats = 0 '\000', fn_extra = 0xd68, fn_mcxt = 0x55f60000000f, fn_expr = 0x55f6e599bce0}, sk_argument = 4}, {sk_flags = 0, sk_attno = 0, sk_strategy = 0, sk_subtype = 3852057829, sk_collation = 22006, sk_func = {fn_addr = 0x10d14c670, fn_oid = 0, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 64 '@', fn_extra = 0x55f6e737d320, fn_mcxt = 0x0, fn_expr = 0x0}, sk_argument = 140720527951536}, {sk_flags = -448403823, sk_attno = 22006, sk_strategy = 0, sk_subtype = 219465476, sk_collation = 32764, sk_func = {fn_addr = 0xdee3eb76d8, fn_oid = 3879362624, fn_nargs = 22006, fn_strict = false, fn_retset = false, fn_stats = 64 '@', fn_extra = 0x7ffc0d14c6d0, fn_mcxt = 0x3000000018, fn_expr = 0x7ffc0d14cd60}, sk_argument = 140720527953056}, {sk_flags = 219466288, sk_attno = 32764, sk_strategy = 0, sk_subtype = 3846551929, sk_collation = 22006, sk_func = {fn_addr = 0x10d14c720, fn_oid = 219472848, fn_nargs = 32764, fn_strict = false, fn_retset = false, fn_stats = 233 '\351', fn_extra = 0x55f6e737ee88, fn_mcxt = 0x830c00000d14c720, fn_expr = 0x7f0de3d85b80}, sk_argument = 1}, {sk_flags = 15625616, sk_attno = 0, sk_strategy = 8192, sk_subtype = 219465712, sk_collation = 32764, sk_func = {fn_addr = 0x55f6e55940dd <BufferAlloc+238>, fn_oid = 3, fn_nargs = 32525, fn_strict = false, fn_retset = false, fn_stats = 67 'C', fn_extra = 0x0, fn_mcxt = 0xde73ad0e8, fn_expr = 0x7f7000000000}, sk_argument = 94518930136320}, {sk_flags = 48, sk_attno = 0, sk_strategy = 0, sk_subtype = 3879362680, sk_collation = 22006, sk_func = {fn_addr = 0x4d430001, fn_oid = 3879362728, fn_nargs = 22006, fn_strict = false, fn_retset = false, fn_stats = 1 '\001', fn_extra = 0x0, fn_mcxt = 0x0, fn_expr = 0x0}, sk_argument = 1296236544}, {sk_flags = -415604568, sk_attno = 22006, sk_strategy = 0, sk_subtype = 1, sk_collation = 0, sk_func = {fn_addr = 0x0, fn_oid = 0, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 0 '\000', fn_extra = 0x0, fn_mcxt = 0x0, fn_expr = 0x0}, sk_argument = 94518929678504}, {sk_flags = 219466336, sk_attno = 32764, sk_strategy = 0, sk_subtype = 3849821366, sk_collation = 22006, sk_func = {fn_addr = 0x30, fn_oid = 3879195424, fn_nargs = 22006, fn_strict = false, fn_retset = false, fn_stats = 240 '\360', fn_extra = 0x55f6e5752d7a <FunctionCall2Coll+160>, fn_mcxt = 0x4002, fn_expr = 0x4006}, sk_argument = 219465824}, {sk_flags = -415765464, sk_attno = 22006, sk_strategy = 0, sk_subtype = 3879201832, sk_collation = 22006, sk_func = {fn_addr = 0x0, fn_oid = 0, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 0 '\000', fn_extra = 0x4006, fn_mcxt = 0x4002, fn_expr = 0x7ffc0d14d620}, sk_argument = 0}, {sk_flags = 0, sk_attno = 0, sk_strategy = 0, sk_subtype = 0, sk_collation = 163584, sk_func = {fn_addr = 0x4000, fn_oid = 16386, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 192 '\300', fn_extra = 0x7f0de4ed1700, fn_mcxt = 0x10d14c8d0, fn_expr = 0xc36e3d82984}, sk_argument = 140720527952208}, {sk_flags = -445281983, sk_attno = 22006, sk_strategy = 0, sk_subtype = 0, sk_collation = 1574, sk_func = {fn_addr = 0x69c55c3600000000, fn_oid = 219466224, fn_nargs = -5170, fn_strict = 64, fn_retset = 131, fn_stats = 0 '\000', fn_extra = 0x55f6e5723c42 <int4hashfast+23>, fn_mcxt = 0x626, fn_expr = 0x7ffc0d14c960}, sk_argument = 94518899785832}, {sk_flags = 1574, sk_attno = 0, sk_strategy = 0, sk_subtype = 3879362624, sk_collation = 22006, sk_func = {fn_addr = 0x0, fn_oid = 20, fn_nargs = 1574, fn_strict = false, fn_retset = false, fn_stats = 1 '\001', fn_extra = 0x55f6e73a6060, fn_mcxt = 0x18, fn_expr = 0x0}, sk_argument = 0}, {sk_flags = 8408, sk_attno = 0, sk_strategy = 0, sk_subtype = 1296236544, sk_collation = 107, sk_func = {fn_addr = 0x7, fn_oid = 0, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 112 'p', fn_extra = 0x2100, fn_mcxt = 0x55f6e743c868, fn_expr = 0xffffffffffffffb0}, sk_argument = 131}, {sk_flags = 72, sk_attno = 0, sk_strategy = 0, sk_subtype = 3879979192, sk_collation = 22006, sk_func = {fn_addr = 0x4d430001, fn_oid = 3879979264, fn_nargs = 22006, fn_strict = false, fn_retset = false, fn_stats = 1 '\001', fn_extra = 0x0, fn_mcxt = 0x0, fn_expr = 0x0}, sk_argument = 1296236544}, {sk_flags = -414988032, sk_attno = 22006, sk_strategy = 0, sk_subtype = 1, sk_collation = 0, sk_func = {fn_addr = 0x0, fn_oid = 0, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 0 '\000', fn_extra = 0x48, fn_mcxt = 0x0, fn_expr = 0x0}, sk_argument = 94518930295040}, {sk_flags = 219466912, sk_attno = 32764, sk_strategy = 0, sk_subtype = 3849821366, sk_collation = 22006, sk_func = {fn_addr = 0x48, fn_oid = 3879978352, fn_nargs = 22006, fn_strict = false, fn_retset = false, fn_stats = 0 '\000', fn_extra = 0x55f6e7442668, fn_mcxt = 0x0, fn_expr = 0x0}, sk_argument = 0}, {sk_flags = 0, sk_attno = 0, sk_strategy = 0, sk_subtype = 1296236544, sk_collation = 0, sk_func = {fn_addr = 0x55f6e74405b8, fn_oid = 16, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 0 '\000', fn_extra = 0x0, fn_mcxt = 0x0, fn_expr = 0x4d430000}, sk_argument = 94518930294424}, {sk_flags = 16, sk_attno = 0, sk_strategy = 0, sk_subtype = 0, sk_collation = 0, sk_func = {fn_addr = 0x0, fn_oid = 0, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 0 '\000', fn_extra = 0x55f6e743c7f0, fn_mcxt = 0x7ffc0d14cd60, fn_expr = 0x55f6e5779cb6 <AllocSetAlloc+2370>}, sk_argument = 40}, {sk_flags = -414988944, sk_attno = 22006, sk_strategy = 0, sk_subtype = 4222451713, sk_collation = 0, sk_func = {fn_addr = 0x7ffc0d14cd70, fn_oid = 219467120, fn_nargs = 32764, fn_strict = false, fn_retset = false, fn_stats = 112 'p', fn_extra = 0x7ffc0d14cd70, fn_mcxt = 0x7ffc0d14cd8a, fn_expr = 0x4d430001}, sk_argument = 94518930294792}, {sk_flags = 24, sk_attno = 0, sk_strategy = 0, sk_subtype = 0, sk_collation = 0, sk_func = {fn_addr = 0x0, fn_oid = 0, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 1 '\001', fn_extra = 0x55f6e743c8a0, fn_mcxt = 0x18, fn_expr = 0x0}, sk_argument = 0}, {sk_flags = 0, sk_attno = 0, sk_strategy = 0, sk_subtype = 1296236544, sk_collation = 0, sk_func = {fn_addr = 0x55f6e743c900, fn_oid = 56, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 0 '\000', fn_extra = 0x0, fn_mcxt = 0x0, fn_expr = 0x4d430000}, sk_argument = 94518930294944}} notnullkeys = {{sk_flags = 0, sk_attno = 0, sk_strategy = 0, sk_subtype = 0, sk_collation = 32525, sk_func = {fn_addr = 0x0, fn_oid = 219462368, fn_nargs = 32764, fn_strict = false, fn_retset = false, fn_stats = 32 ' ', fn_extra = 0x7ffc0d14bec8, fn_mcxt = 0x7ffc00000006, fn_expr = 0x0}, sk_argument = 3432}, {sk_flags = 6, sk_attno = 0, sk_strategy = 0, sk_subtype = 3852235000, sk_collation = 22006, sk_func = {fn_addr = 0x0, fn_oid = 3879363928, fn_nargs = 21761, fn_strict = false, fn_retset = false, fn_stats = 253 '\375', fn_extra = 0x830c000100000001, fn_mcxt = 0x830c000000212ded, fn_expr = 0x55f6e5ad2ca0 <PrivateRefCountArray>}, sk_argument = 8512178059852}, {sk_flags = 219462288, sk_attno = 32764, sk_strategy = 0, sk_subtype = 3847845018, sk_collation = 22006, sk_func = {fn_addr = 0x0, fn_oid = 3823855104, fn_nargs = 1981, fn_strict = false, fn_retset = false, fn_stats = 176 '\260', fn_extra = 0x55f6e5210e53 <_bt_drop_lock_and_maybe_pin+128>, fn_mcxt = 0x55f6e743a5f8, fn_expr = 0x55f6e737e3a0}, sk_argument = 140720527953520}, {sk_flags = 8, sk_attno = 48, sk_strategy = 0, sk_subtype = 219464144, sk_collation = 32764, sk_func = {fn_addr = 0x7ffc0d14c110, fn_oid = 1315532320, fn_nargs = 5, fn_strict = false, fn_retset = false, fn_stats = 16 '\020', fn_extra = 0x550495020, fn_mcxt = 0x551830710, fn_expr = 0x552293220}, sk_argument = 22873827600}, {sk_flags = 1409881120, sk_attno = 5, sk_strategy = 0, sk_subtype = 1430440720, sk_collation = 5, sk_func = {fn_addr = 0x555e8f620, fn_oid = 1461890320, fn_nargs = 5, fn_strict = false, fn_retset = false, fn_stats = 56 '8', fn_extra = 0x55f6e737e138, fn_mcxt = 0x559b1f4a0, fn_expr = 0x55aebab90}, sk_argument = 23011120800}, {sk_flags = 1556843920, sk_attno = 5, sk_strategy = 0, sk_subtype = 1567733920, sk_collation = 5, sk_func = {fn_addr = 0x55eab6f90, fn_oid = 1599183520, fn_nargs = 5, fn_strict = false, fn_retset = false, fn_stats = 144 '\220', fn_extra = 0x561317ca0, fn_mcxt = 0x5626b3390, fn_expr = 0x563115ea0}, sk_argument = 23157478800}, {sk_flags = 1694137120, sk_attno = 5, sk_strategy = 0, sk_subtype = 1714696720, sk_collation = 5, sk_func = {fn_addr = 0x566da5d20, fn_oid = 1746146320, fn_nargs = 5, fn_strict = false, fn_retset = false, fn_stats = 32 ' ', fn_extra = 0x569f3f610, fn_mcxt = 0x56a9a2120, fn_expr = 0x56bd3d810}, sk_argument = 23294772000}, {sk_flags = 1840495120, sk_attno = 5, sk_strategy = 0, sk_subtype = 1851989920, sk_collation = 5, sk_func = {fn_addr = 0x56f9cd690, fn_oid = 1883439520, fn_nargs = 5, fn_strict = false, fn_retset = false, fn_stats = 144 '\220', fn_extra = 0x57222e3a0, fn_mcxt = 0x5735c9a90, fn_expr = 0x57402c5a0}, sk_argument = 23441734800}, {sk_flags = 1977788320, sk_attno = 5, sk_strategy = 0, sk_subtype = 1998347920, sk_collation = 5, sk_func = {fn_addr = 0x577c289a0, fn_oid = 2029797520, fn_nargs = 5, fn_strict = false, fn_retset = false, fn_stats = 32 ' ', fn_extra = 0x57ae55d10, fn_mcxt = 0x100030000, fn_expr = 0x0}, sk_argument = 94518929514432}, {sk_flags = 356, sk_attno = 2, sk_strategy = 1, sk_subtype = 40, sk_collation = 0, sk_func = {fn_addr = 0x55f6e73a5fc0, fn_oid = 1296236545, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 232 '\350', fn_extra = 0x1, fn_mcxt = 0x0, fn_expr = 0x0}, sk_argument = 0}, {sk_flags = 1296236544, sk_attno = 0, sk_strategy = 0, sk_subtype = 3879362536, sk_collation = 22006, sk_func = {fn_addr = 0x1, fn_oid = 0, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 0 '\000', fn_extra = 0x0, fn_mcxt = 0x7ffc0d14c0c0, fn_expr = 0x0}, sk_argument = 0}, {sk_flags = -415604760, sk_attno = 22006, sk_strategy = 0, sk_subtype = 219463536, sk_collation = 32764, sk_func = {fn_addr = 0x55f6e5779cb6 <AllocSetAlloc+2370>, fn_oid = 40, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 32 ' ', fn_extra = 0x0, fn_mcxt = 0x2000000000064, fn_expr = 0x4eb}, sk_argument = 1259}, {sk_flags = 1259, sk_attno = 0, sk_strategy = 0, sk_subtype = 219463056, sk_collation = 32764, sk_func = {fn_addr = 0x337dafc200000028, fn_oid = 1259, fn_nargs = 1259, fn_strict = false, fn_retset = false, fn_stats = 64 '@', fn_extra = 0x55f6e5752d7a <FunctionCall2Coll+160>, fn_mcxt = 0x4eb, fn_expr = 0x4eb}, sk_argument = 429496729600}, {sk_flags = -414987040, sk_attno = 22006, sk_strategy = 0, sk_subtype = 3879980256, sk_collation = 22006, sk_func = {fn_addr = 0x0, fn_oid = 0, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 100 'd', fn_extra = 0x4eb, fn_mcxt = 0x80, fn_expr = 0xd14cb70}, sk_argument = 17179869199}, {sk_flags = 219463744, sk_attno = 32764, sk_strategy = 0, sk_subtype = 3849819694, sk_collation = 22006, sk_func = {fn_addr = 0x80, fn_oid = 3879978352, fn_nargs = 22006, fn_strict = false, fn_retset = false, fn_stats = 48 '0', fn_extra = 0x7f0de4ed1700, fn_mcxt = 0x7ffc0d14be30, fn_expr = 0x1c6e55c6297}, sk_argument = 140720527949472}, {sk_flags = -445281983, sk_attno = 22006, sk_strategy = 0, sk_subtype = 0, sk_collation = 0, sk_func = {fn_addr = 0xad8dc1c600000000, fn_oid = 219463488, fn_nargs = 32764, fn_strict = false, fn_retset = false, fn_stats = 248 '\370', fn_extra = 0x4d430001, fn_mcxt = 0x55f6e73a5fa8, fn_expr = 0x18}, sk_argument = 0}, {sk_flags = 0, sk_attno = 0, sk_strategy = 0, sk_subtype = 0, sk_collation = 0, sk_func = {fn_addr = 0x4d430000, fn_oid = 3879362536, fn_nargs = 22006, fn_strict = false, fn_retset = false, fn_stats = 24 '\030', fn_extra = 0x0, fn_mcxt = 0x0, fn_expr = 0x0}, sk_argument = 1296236544}, {sk_flags = -415604824, sk_attno = 22006, sk_strategy = 0, sk_subtype = 16, sk_collation = 0, sk_func = {fn_addr = 0x0, fn_oid = 0, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 0 '\000', fn_extra = 0x7ffc0d14bf10, fn_mcxt = 0x0, fn_expr = 0x0}, sk_argument = 0}, {sk_flags = 219463904, sk_attno = 32764, sk_strategy = 0, sk_subtype = 0, sk_collation = 0, sk_func = {fn_addr = 0x7ffc0d14c170, fn_oid = 3849819694, fn_nargs = 22006, fn_strict = false, fn_retset = false, fn_stats = 8 '\b', fn_extra = 0x55f6e73a12b0, fn_mcxt = 0x55f6e743ceb8, fn_expr = 0x3e743ceb8}, sk_argument = 94518929678248}, {sk_flags = 64, sk_attno = 0, sk_strategy = 0, sk_subtype = 3879195424, sk_collation = 22006, sk_func = {fn_addr = 0x55f6e743ceb8, fn_oid = 3879980855, fn_nargs = 22006, fn_strict = false, fn_retset = false, fn_stats = 104 'h', fn_extra = 0x0, fn_mcxt = 0x55f6e73a5b10, fn_expr = 0x7ffc0d14bff0}, sk_argument = 94518900186290}, {sk_flags = 1296236544, sk_attno = 0, sk_strategy = 0, sk_subtype = 40, sk_collation = 0, sk_func = {fn_addr = 0x1305, fn_oid = 3879195424, fn_nargs = 22006, fn_strict = false, fn_retset = false, fn_stats = 192 '\300', fn_extra = 0x28, fn_mcxt = 0x0, fn_expr = 0x0}, sk_argument = 128}, {sk_flags = 0, sk_attno = 0, sk_strategy = 0, sk_subtype = 3879362496, sk_collation = 22006, sk_func = {fn_addr = 0x55f6e737d320, fn_oid = 0, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 0 '\000', fn_extra = 0x7ffc0d14c350, fn_mcxt = 0x55f6e545a384 <expression_tree_mutator+222>, fn_expr = 0x55f6e743cea0}, sk_argument = 140720527958992}, {sk_flags = -447769879, sk_attno = 22006, sk_strategy = 0, sk_subtype = 3879202312, sk_collation = 22006, sk_func = {fn_addr = 0x8, fn_oid = 5840, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 0 '\000', fn_extra = 0x55f6e73b07a0, fn_mcxt = 0x0, fn_expr = 0x0}, sk_argument = 0}, {sk_flags = 0, sk_attno = 0, sk_strategy = 0, sk_subtype = 1296236544, sk_collation = 0, sk_func = {fn_addr = 0x55f6e73b0708, fn_oid = 16, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 0 '\000', fn_extra = 0x0, fn_mcxt = 0x7ffc0d14c0d0, fn_expr = 0x80}, sk_argument = 720304670261248}, {sk_flags = 219464832, sk_attno = 32764, sk_strategy = 0, sk_subtype = 3849661818, sk_collation = 22006, sk_func = {fn_addr = 0x4000, fn_oid = 167709, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 0 '\000', fn_extra = 0x7ffc0d14cf30, fn_mcxt = 0x7ffc0d14cf30, fn_expr = 0x0}, sk_argument = 0}, {sk_flags = 0, sk_attno = 0, sk_strategy = 2, sk_subtype = 167709, sk_collation = 0, sk_func = {fn_addr = 0x4000, fn_oid = 167709, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 80 'P', fn_extra = 0x0, fn_mcxt = 0x400200004000, fn_expr = 0x7ffc0d14c500}, sk_argument = 94518899977594}, {sk_flags = 16384, sk_attno = 0, sk_strategy = 0, sk_subtype = 16386, sk_collation = 0, sk_func = {fn_addr = 0xe73a12b0, fn_oid = 3879979168, fn_nargs = 22006, fn_strict = false, fn_retset = false, fn_stats = 160 '\240', fn_extra = 0x0, fn_mcxt = 0x0, fn_expr = 0x2000000000000}, sk_argument = 16386}, {sk_flags = 16384, sk_attno = 0, sk_strategy = 0, sk_subtype = 219467568, sk_collation = 32764, sk_func = {fn_addr = 0x0, fn_oid = 0, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 0 '\000', fn_extra = 0x305c, fn_mcxt = 0x4000, fn_expr = 0x69c55c360d14c1d0}, sk_argument = 139697652045568}, {sk_flags = 219464160, sk_attno = 1, sk_strategy = 0, sk_subtype = 3822594436, sk_collation = 3126, sk_func = {fn_addr = 0x7ffc0d14c260, fn_oid = 3849685313, fn_nargs = 22006, fn_strict = false, fn_retset = false, fn_stats = 0 '\000', fn_extra = 0x69c55c3600000000, fn_mcxt = 0x7ffc0d14c300, fn_expr = 0x83140001e73780f8}, sk_argument = 140720527950452}, {sk_flags = -471124968, sk_attno = 32525, sk_strategy = 0, sk_subtype = 1781, sk_collation = 1, sk_func = {fn_addr = 0x7f0de3d83d84, fn_oid = 219464256, fn_nargs = 32764, fn_strict = false, fn_retset = false, fn_stats = 156 '\234', fn_extra = 0x10d14c250, fn_mcxt = 0x7f0de3d83d84, fn_expr = 0x7ffc0d14c260}, sk_argument = 94518898344476}, {sk_flags = 219464336, sk_attno = 1, sk_strategy = 0, sk_subtype = 3822599556, sk_collation = 32525, sk_func = {fn_addr = 0x7ffc0d14c290, fn_oid = 3848037015, fn_nargs = 22006, fn_strict = false, fn_retset = false, fn_stats = 144 '\220', fn_extra = 0x7f0de3d83d80, fn_mcxt = 0x1, fn_expr = 0x2000000000ee9c10}, sk_argument = 140720527950688}, {sk_flags = -447135523, sk_attno = 22006, sk_strategy = 0, sk_subtype = 3, sk_collation = 0, sk_func = {fn_addr = 0x7ffc0d14c3b3, fn_oid = 0, fn_nargs = 0, fn_strict = false, fn_retset = false, fn_stats = 16 '\020', fn_extra = 0x7f7000000000, fn_mcxt = 0x55f6e7415de0, fn_expr = 0x7f0de3d82980}, sk_argument = 8204046756560287030}} keysCount = 1 i = 1 status = true strat_total = 3 currItem = 0x0 blkno = 2198601728 __func__ = "_bt_first" #12 0x000055f6e520ea2a in btgettuple (scan=0x55f6e743c6b0, dir=ForwardScanDirection) at /home/andres/src/postgresql/src/backend/access/nbtree/nbtree.c:245 so = 0x55f6e74405d0 res = false #13 0x000055f6e5201a6a in index_getnext_tid (scan=0x55f6e743c6b0, direction=ForwardScanDirection) at /home/andres/src/postgresql/src/backend/access/index/indexam.c:541 found = false __func__ = "index_getnext_tid" #14 0x000055f6e5201ee1 in index_getnext (scan=0x55f6e743c6b0, direction=ForwardScanDirection) at /home/andres/src/postgresql/src/backend/access/index/indexam.c:679 heapTuple = 0x55f6e5aadec0 <CatalogSnapshotData+64> tid = 0x7ffc0d14ce60 #15 0x000055f6e5200347 in systable_getnext (sysscan=0x55f6e743c7c8) at /home/andres/src/postgresql/src/backend/access/index/genam.c:411 htup = 0x7f0de627a850 __func__ = "systable_getnext" #16 0x000055f6e5733253 in ScanPgRelation (targetRelId=1259, indexOK=true, force_non_historic=false) at /home/andres/src/postgresql/src/backend/utils/cache/relcache.c:358 pg_class_tuple = 0x55f6e5aae2c0 <TopTransactionStateData> pg_class_desc = 0x7f0de3d472b0 pg_class_scan = 0x55f6e743c7c8 key = {{sk_flags = 0, sk_attno = 1, sk_strategy = 3, sk_subtype = 0, sk_collation = 100, sk_func = {fn_addr = 0x55f6e569cbf8 <oideq>, fn_oid = 184, fn_nargs = 2, fn_strict = true, fn_retset = false, fn_stats = 2 '\002', fn_extra = 0x0, fn_mcxt = 0x55f6e743c570, fn_expr = 0x0}, sk_argument = 1259}} snapshot = 0x55f6e5aade80 <CatalogSnapshotData> __func__ = "ScanPgRelation" #17 0x000055f6e5736fd0 in RelationReloadNailed (relation=0x7f0de3d472b0) at /home/andres/src/postgresql/src/backend/utils/cache/relcache.c:2208 pg_class_tuple = 0x4e73b0540 relp = 0x7f0de3d472c0 #18 0x000055f6e5737414 in RelationClearRelation (relation=0x7f0de3d472b0, rebuild=true) at /home/andres/src/postgresql/src/backend/utils/cache/relcache.c:2343 __func__ = "RelationClearRelation" #19 0x000055f6e5737aaf in RelationFlushRelation (relation=0x7f0de3d472b0) at /home/andres/src/postgresql/src/backend/utils/cache/relcache.c:2584 rebuild = true #20 0x000055f6e5737bc8 in RelationCacheInvalidateEntry (relationId=1259) at /home/andres/src/postgresql/src/backend/utils/cache/relcache.c:2636 relation = 0x7f0de3d472b0 #21 0x000055f6e5728fe4 in LocalExecuteInvalidationMessage (msg=0x7ffc0d14d220) at /home/andres/src/postgresql/src/backend/utils/cache/inval.c:587 i = 20 __func__ = "LocalExecuteInvalidationMessage" #22 0x000055f6e55b27c0 in ReceiveSharedInvalidMessages (invalFunction=0x55f6e5728edd <LocalExecuteInvalidationMessage>, resetFunction=0x55f6e5729149 <InvalidateSystemCaches>) at /home/andres/src/postgresql/src/backend/storage/ipc/sinval.c:121 msg = {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 1259}, cat = {id = -2 '\376', dbId = 12397, catId = 1259}, rc = {id = -2 '\376', dbId = 12397, relId = 1259}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 1259, relNode = 22006}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 1259}} getResult = 20 messages = {{id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 1259}, cat = {id = -2 '\376', dbId = 12397, catId = 1259}, rc = {id = -2 '\376', dbId = 12397, relId = 1259}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 1259, relNode = 22006}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 1259}}, {id = -5 '\373', cc = {id = -5 '\373', dbId = 12397, hashValue = 2608}, cat = {id = -5 '\373', dbId = 12397, catId = 2608}, rc = {id = -5 '\373', dbId = 12397, relId = 2608}, sm = {id = -5 '\373', backend_hi = -37 '\333', backend_lo = 3348, rnode = {spcNode = 12397, dbNode = 2608, relNode = 11}}, rm = {id = -5 '\373', dbId = 12397}, sn = {id = -5 '\373', dbId = 12397, relId = 2608}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 1259}, cat = {id = -2 '\376', dbId = 12397, catId = 1259}, rc = {id = -2 '\376', dbId = 12397, relId = 1259}, sm = {id = -2 '\376', backend_hi = -38 '\332', backend_lo = 3348, rnode = {spcNode = 12397, dbNode = 1259, relNode = 22006}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 1259}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 3455}, cat = {id = -2 '\376', dbId = 12397, catId = 3455}, rc = {id = -2 '\376', dbId = 12397, relId = 3455}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 3455, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 3455}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 3455}, cat = {id = -2 '\376', dbId = 12397, catId = 3455}, rc = {id = -2 '\376', dbId = 12397, relId = 3455}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 3455, relNode = 22006}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 3455}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 1259}, cat = {id = -2 '\376', dbId = 12397, catId = 1259}, rc = {id = -2 '\376', dbId = 12397, relId = 1259}, sm = {id = -2 '\376', backend_hi = -38 '\332', backend_lo = 3348, rnode = {spcNode = 12397, dbNode = 1259, relNode = 22006}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 1259}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 2663}, cat = {id = -2 '\376', dbId = 12397, catId = 2663}, rc = {id = -2 '\376', dbId = 12397, relId = 2663}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 2663, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 2663}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 2663}, cat = {id = -2 '\376', dbId = 12397, catId = 2663}, rc = {id = -2 '\376', dbId = 12397, relId = 2663}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 2663, relNode = 22006}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 2663}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 1259}, cat = {id = -2 '\376', dbId = 12397, catId = 1259}, rc = {id = -2 '\376', dbId = 12397, relId = 1259}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 1259, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 1259}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 2662}, cat = {id = -2 '\376', dbId = 12397, catId = 2662}, rc = {id = -2 '\376', dbId = 12397, relId = 2662}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 2662, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 2662}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 2662}, cat = {id = -2 '\376', dbId = 12397, catId = 2662}, rc = {id = -2 '\376', dbId = 12397, relId = 2662}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 2662, relNode = 22006}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 2662}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 1259}, cat = {id = -2 '\376', dbId = 12397, catId = 1259}, rc = {id = -2 '\376', dbId = 12397, relId = 1259}, sm = {id = -2 '\376', backend_hi = 0 '\000', backend_lo = 0, rnode = {spcNode = 12397, dbNode = 1259, relNode = 32525}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 1259}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 167949}, cat = {id = -2 '\376', dbId = 12397, catId = 167949}, rc = {id = -2 '\376', dbId = 12397, relId = 167949}, sm = {id = -2 '\376', backend_hi = 0 '\000', backend_lo = 0, rnode = {spcNode = 12397, dbNode = 167949, relNode = 11}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 167949}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 167949}, cat = {id = -2 '\376', dbId = 12397, catId = 167949}, rc = {id = -2 '\376', dbId = 12397, relId = 167949}, sm = {id = -2 '\376', backend_hi = 0 '\000', backend_lo = 0, rnode = {spcNode = 12397, dbNode = 167949, relNode = 32525}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 167949}}, {id = -5 '\373', cc = {id = -5 '\373', dbId = 12397, hashValue = 2608}, cat = {id = -5 '\373', dbId = 12397, catId = 2608}, rc = {id = -5 '\373', dbId = 12397, relId = 2608}, sm = {id = -5 '\373', backend_hi = -41 '\327', backend_lo = 3348, rnode = {spcNode = 12397, dbNode = 2608, relNode = 11}}, rm = {id = -5 '\373', dbId = 12397}, sn = {id = -5 '\373', dbId = 12397, relId = 2608}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 167949}, cat = {id = -2 '\376', dbId = 12397, catId = 167949}, rc = {id = -2 '\376', dbId = 12397, relId = 167949}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 167949, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 167949}}, {id = -3 '\375', cc = {id = -3 '\375', dbId = 1663, hashValue = 12397}, cat = {id = -3 '\375', dbId = 1663, catId = 12397}, rc = {id = -3 '\375', dbId = 1663, relId = 12397}, sm = {id = -3 '\375', backend_hi = -1 '\377', backend_lo = 65535, rnode = {spcNode = 1663, dbNode = 12397, relNode = 167943}}, rm = {id = -3 '\375', dbId = 1663}, sn = {id = -3 '\375', dbId = 1663, relId = 12397}}, {id = -3 '\375', cc = {id = -3 '\375', dbId = 1663, hashValue = 12397}, cat = {id = -3 '\375', dbId = 1663, catId = 12397}, rc = {id = -3 '\375', dbId = 1663, relId = 12397}, sm = {id = -3 '\375', backend_hi = -1 '\377', backend_lo = 65535, rnode = {spcNode = 1663, dbNode = 12397, relNode = 167948}}, rm = {id = -3 '\375', dbId = 1663}, sn = {id = -3 '\375', dbId = 1663, relId = 12397}}, {id = -3 '\375', cc = {id = -3 '\375', dbId = 1663, hashValue = 12397}, cat = {id = -3 '\375', dbId = 1663, catId = 12397}, rc = {id = -3 '\375', dbId = 1663, relId = 12397}, sm = {id = -3 '\375', backend_hi = -1 '\377', backend_lo = 65535, rnode = {spcNode = 1663, dbNode = 12397, relNode = 167947}}, rm = {id = -3 '\375', dbId = 1663}, sn = {id = -3 '\375', dbId = 1663, relId = 12397}}, {id = -3 '\375', cc = {id = -3 '\375', dbId = 1663, hashValue = 12397}, cat = {id = -3 '\375', dbId = 1663, catId = 12397}, rc = {id = -3 '\375', dbId = 1663, relId = 12397}, sm = {id = -3 '\375', backend_hi = -1 '\377', backend_lo = 65535, rnode = {spcNode = 1663, dbNode = 12397, relNode = 167946}}, rm = {id = -3 '\375', dbId = 1663}, sn = {id = -3 '\375', dbId = 1663, relId = 12397}}, {id = 7 '\a', cc = {id = 7 '\a', dbId = 12397, hashValue = 1528188348}, cat = {id = 7 '\a', dbId = 12397, catId = 1528188348}, rc = {id = 7 '\a', dbId = 12397, relId = 1528188348}, sm = {id = 7 '\a', backend_hi = -10 '\366', backend_lo = 58325, rnode = {spcNode = 12397, dbNode = 1528188348, relNode = 22006}}, rm = {id = 7 '\a', dbId = 12397}, sn = {id = 7 '\a', dbId = 12397, relId = 1528188348}}, {id = 6 '\006', cc = {id = 6 '\006', dbId = 12397, hashValue = 2483940397}, cat = {id = 6 '\006', dbId = 12397, catId = 2483940397}, rc = {id = 6 '\006', dbId = 12397, relId = 2483940397}, sm = {id = 6 '\006', backend_hi = 7 '\a', backend_lo = 58326, rnode = {spcNode = 12397, dbNode = 2483940397, relNode = 22006}}, rm = {id = 6 '\006', dbId = 12397}, sn = {id = 6 '\006', dbId = 12397, relId = 2483940397}}, {id = 7 '\a', cc = {id = 7 '\a', dbId = 12397, hashValue = 37473943}, cat = {id = 7 '\a', dbId = 12397, catId = 37473943}, rc = {id = 7 '\a', dbId = 12397, relId = 37473943}, sm = {id = 7 '\a', backend_hi = -10 '\366', backend_lo = 58325, rnode = {spcNode = 12397, dbNode = 37473943, relNode = 22006}}, rm = {id = 7 '\a', dbId = 12397}, sn = {id = 7 '\a', dbId = 12397, relId = 37473943}}, {id = 6 '\006', cc = {id = 6 '\006', dbId = 12397, hashValue = 2828489776}, cat = {id = 6 '\006', dbId = 12397, catId = 2828489776}, rc = {id = 6 '\006', dbId = 12397, relId = 2828489776}, sm = {id = 6 '\006', backend_hi = 7 '\a', backend_lo = 58326, rnode = {spcNode = 12397, dbNode = 2828489776, relNode = 22006}}, rm = {id = 6 '\006', dbId = 12397}, sn = {id = 6 '\006', dbId = 12397, relId = 2828489776}}, {id = 7 '\a', cc = {id = 7 '\a', dbId = 12397, hashValue = 2277595885}, cat = {id = 7 '\a', dbId = 12397, catId = 2277595885}, rc = {id = 7 '\a', dbId = 12397, relId = 2277595885}, sm = {id = 7 '\a', backend_hi = -10 '\366', backend_lo = 58325, rnode = {spcNode = 12397, dbNode = 2277595885, relNode = 22006}}, rm = {id = 7 '\a', dbId = 12397}, sn = {id = 7 '\a', dbId = 12397, relId = 2277595885}}, {id = 6 '\006', cc = {id = 6 '\006', dbId = 12397, hashValue = 3442084044}, cat = {id = 6 '\006', dbId = 12397, catId = 3442084044}, rc = {id = 6 '\006', dbId = 12397, relId = 3442084044}, sm = {id = 6 '\006', backend_hi = 7 '\a', backend_lo = 58326, rnode = {spcNode = 12397, dbNode = 3442084044, relNode = 22006}}, rm = {id = 6 '\006', dbId = 12397}, sn = {id = 6 '\006', dbId = 12397, relId = 3442084044}}, {id = 7 '\a', cc = {id = 7 '\a', dbId = 12397, hashValue = 2945592578}, cat = {id = 7 '\a', dbId = 12397, catId = 2945592578}, rc = {id = 7 '\a', dbId = 12397, relId = 2945592578}, sm = {id = 7 '\a', backend_hi = -10 '\366', backend_lo = 58325, rnode = {spcNode = 12397, dbNode = 2945592578, relNode = 22006}}, rm = {id = 7 '\a', dbId = 12397}, sn = {id = 7 '\a', dbId = 12397, relId = 2945592578}}, {id = 6 '\006', cc = {id = 6 '\006', dbId = 12397, hashValue = 134785355}, cat = {id = 6 '\006', dbId = 12397, catId = 134785355}, rc = {id = 6 '\006', dbId = 12397, relId = 134785355}, sm = {id = 6 '\006', backend_hi = 7 '\a', backend_lo = 58326, rnode = {spcNode = 12397, dbNode = 134785355, relNode = 22006}}, rm = {id = 6 '\006', dbId = 12397}, sn = {id = 6 '\006', dbId = 12397, relId = 134785355}}, {id = 7 '\a', cc = {id = 7 '\a', dbId = 12397, hashValue = 2621623531}, cat = {id = 7 '\a', dbId = 12397, catId = 2621623531}, rc = {id = 7 '\a', dbId = 12397, relId = 2621623531}, sm = {id = 7 '\a', backend_hi = -10 '\366', backend_lo = 58325, rnode = {spcNode = 12397, dbNode = 2621623531, relNode = 22006}}, rm = {id = 7 '\a', dbId = 12397}, sn = {id = 7 '\a', dbId = 12397, relId = 2621623531}}, {id = 6 '\006', cc = {id = 6 '\006', dbId = 12397, hashValue = 3549520513}, cat = {id = 6 '\006', dbId = 12397, catId = 3549520513}, rc = {id = 6 '\006', dbId = 12397, relId = 3549520513}, sm = {id = 6 '\006', backend_hi = 7 '\a', backend_lo = 58326, rnode = {spcNode = 12397, dbNode = 3549520513, relNode = 22006}}, rm = {id = 6 '\006', dbId = 12397}, sn = {id = 6 '\006', dbId = 12397, relId = 3549520513}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 167949}, cat = {id = -2 '\376', dbId = 12397, catId = 167949}, rc = {id = -2 '\376', dbId = 12397, relId = 167949}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 167949, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 167949}}, {id = -5 '\373', cc = {id = -5 '\373', dbId = 12397, hashValue = 2608}, cat = {id = -5 '\373', dbId = 12397, catId = 2608}, rc = {id = -5 '\373', dbId = 12397, relId = 2608}, sm = {id = -5 '\373', backend_hi = -37 '\333', backend_lo = 3348, rnode = {spcNode = 12397, dbNode = 2608, relNode = 11}}, rm = {id = -5 '\373', dbId = 12397}, sn = {id = -5 '\373', dbId = 12397, relId = 2608}}} nextmsg = 1 nummsgs = 20 __func__ = "ReceiveSharedInvalidMessages" #23 0x000055f6e5729223 in AcceptInvalidationMessages () at /home/andres/src/postgresql/src/backend/utils/cache/inval.c:681 No locals. #24 0x000055f6e55b6825 in LockRelationOid (relid=2662, lockmode=1) at /home/andres/src/postgresql/src/backend/storage/lmgr/lmgr.c:125 tag = {locktag_field1 = 12397, locktag_field2 = 2662, locktag_field3 = 0, locktag_field4 = 0, locktag_type = 0 '\000', locktag_lockmethodid = 1 '\001'} res = LOCKACQUIRE_OK #25 0x000055f6e51e11f8 in relation_open (relationId=2662, lockmode=1) at /home/andres/src/postgresql/src/backend/access/heap/heapam.c:1132 r = 0x55f6e545f1f6 <list_member_oid+90> __func__ = "relation_open" #26 0x000055f6e5200a77 in index_open (relationId=2662, lockmode=1) at /home/andres/src/postgresql/src/backend/access/index/indexam.c:154 r = 0x55f6e528787f <ReindexIsProcessingIndex+42> __func__ = "index_open" #27 0x000055f6e5200111 in systable_beginscan (heapRelation=0x7f0de3d472b0, indexId=2662, indexOK=true, snapshot=0x55f6e5aade80 <CatalogSnapshotData>, nkeys=1, key=0x7ffc0d14d390) at /home/andres/src/postgresql/src/backend/access/index/genam.c:329 sysscan = 0x55f6e57a285f <GetCatalogSnapshot+39> irel = 0x4eb00000000 __func__ = "systable_beginscan" #28 0x000055f6e5733243 in ScanPgRelation (targetRelId=16390, indexOK=true, force_non_historic=false) at /home/andres/src/postgresql/src/backend/utils/cache/relcache.c:353 pg_class_tuple = 0x55f6e73a8340 pg_class_desc = 0x7f0de3d472b0 pg_class_scan = 0x0 key = {{sk_flags = 0, sk_attno = -2, sk_strategy = 3, sk_subtype = 0, sk_collation = 100, sk_func = {fn_addr = 0x55f6e569cbf8 <oideq>, fn_oid = 184, fn_nargs = 2, fn_strict = true, fn_retset = false, fn_stats = 2 '\002', fn_extra = 0x0, fn_mcxt = 0x55f6e743c570, fn_expr = 0x0}, sk_argument = 16390}} snapshot = 0x55f6e5aade80 <CatalogSnapshotData> __func__ = "ScanPgRelation" #29 0x000055f6e5736c9c in RelationReloadIndexInfo (relation=0x7f0de3d5c020) at /home/andres/src/postgresql/src/backend/utils/cache/relcache.c:2086 indexOK = true pg_class_tuple = 0x7f0de3d5c030 relp = 0x55f6e74152f0 __func__ = "RelationReloadIndexInfo" #30 0x000055f6e5737487 in RelationClearRelation (relation=0x7f0de3d5c020, rebuild=true) at /home/andres/src/postgresql/src/backend/utils/cache/relcache.c:2361 __func__ = "RelationClearRelation" #31 0x000055f6e5737aaf in RelationFlushRelation (relation=0x7f0de3d5c020) at /home/andres/src/postgresql/src/backend/utils/cache/relcache.c:2584 rebuild = true #32 0x000055f6e5737bc8 in RelationCacheInvalidateEntry (relationId=16390) at /home/andres/src/postgresql/src/backend/utils/cache/relcache.c:2636 relation = 0x7f0de3d5c020 #33 0x000055f6e5728fe4 in LocalExecuteInvalidationMessage (msg=0x7ffc0d14d780) at /home/andres/src/postgresql/src/backend/utils/cache/inval.c:587 i = 22006 __func__ = "LocalExecuteInvalidationMessage" #34 0x000055f6e55b26d6 in ReceiveSharedInvalidMessages (invalFunction=0x55f6e5728edd <LocalExecuteInvalidationMessage>, resetFunction=0x55f6e5729149 <InvalidateSystemCaches>) at /home/andres/src/postgresql/src/backend/storage/ipc/sinval.c:91 msg = {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 16390}, cat = {id = -2 '\376', dbId = 12397, catId = 16390}, rc = {id = -2 '\376', dbId = 12397, relId = 16390}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 16390, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 16390}} messages = {{id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 1259}, cat = {id = -2 '\376', dbId = 12397, catId = 1259}, rc = {id = -2 '\376', dbId = 12397, relId = 1259}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 1259, relNode = 22006}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 1259}}, {id = -5 '\373', cc = {id = -5 '\373', dbId = 12397, hashValue = 2608}, cat = {id = -5 '\373', dbId = 12397, catId = 2608}, rc = {id = -5 '\373', dbId = 12397, relId = 2608}, sm = {id = -5 '\373', backend_hi = -37 '\333', backend_lo = 3348, rnode = {spcNode = 12397, dbNode = 2608, relNode = 11}}, rm = {id = -5 '\373', dbId = 12397}, sn = {id = -5 '\373', dbId = 12397, relId = 2608}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 1259}, cat = {id = -2 '\376', dbId = 12397, catId = 1259}, rc = {id = -2 '\376', dbId = 12397, relId = 1259}, sm = {id = -2 '\376', backend_hi = -38 '\332', backend_lo = 3348, rnode = {spcNode = 12397, dbNode = 1259, relNode = 22006}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 1259}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 3455}, cat = {id = -2 '\376', dbId = 12397, catId = 3455}, rc = {id = -2 '\376', dbId = 12397, relId = 3455}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 3455, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 3455}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 3455}, cat = {id = -2 '\376', dbId = 12397, catId = 3455}, rc = {id = -2 '\376', dbId = 12397, relId = 3455}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 3455, relNode = 22006}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 3455}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 1259}, cat = {id = -2 '\376', dbId = 12397, catId = 1259}, rc = {id = -2 '\376', dbId = 12397, relId = 1259}, sm = {id = -2 '\376', backend_hi = -38 '\332', backend_lo = 3348, rnode = {spcNode = 12397, dbNode = 1259, relNode = 22006}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 1259}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 2663}, cat = {id = -2 '\376', dbId = 12397, catId = 2663}, rc = {id = -2 '\376', dbId = 12397, relId = 2663}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 2663, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 2663}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 2663}, cat = {id = -2 '\376', dbId = 12397, catId = 2663}, rc = {id = -2 '\376', dbId = 12397, relId = 2663}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 2663, relNode = 22006}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 2663}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 1259}, cat = {id = -2 '\376', dbId = 12397, catId = 1259}, rc = {id = -2 '\376', dbId = 12397, relId = 1259}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 1259, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 1259}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 2662}, cat = {id = -2 '\376', dbId = 12397, catId = 2662}, rc = {id = -2 '\376', dbId = 12397, relId = 2662}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 2662, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 2662}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 2662}, cat = {id = -2 '\376', dbId = 12397, catId = 2662}, rc = {id = -2 '\376', dbId = 12397, relId = 2662}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 2662, relNode = 22006}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 2662}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 1259}, cat = {id = -2 '\376', dbId = 12397, catId = 1259}, rc = {id = -2 '\376', dbId = 12397, relId = 1259}, sm = {id = -2 '\376', backend_hi = 0 '\000', backend_lo = 0, rnode = {spcNode = 12397, dbNode = 1259, relNode = 32525}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 1259}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 167949}, cat = {id = -2 '\376', dbId = 12397, catId = 167949}, rc = {id = -2 '\376', dbId = 12397, relId = 167949}, sm = {id = -2 '\376', backend_hi = 0 '\000', backend_lo = 0, rnode = {spcNode = 12397, dbNode = 167949, relNode = 11}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 167949}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 167949}, cat = {id = -2 '\376', dbId = 12397, catId = 167949}, rc = {id = -2 '\376', dbId = 12397, relId = 167949}, sm = {id = -2 '\376', backend_hi = 0 '\000', backend_lo = 0, rnode = {spcNode = 12397, dbNode = 167949, relNode = 32525}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 167949}}, {id = -5 '\373', cc = {id = -5 '\373', dbId = 12397, hashValue = 2608}, cat = {id = -5 '\373', dbId = 12397, catId = 2608}, rc = {id = -5 '\373', dbId = 12397, relId = 2608}, sm = {id = -5 '\373', backend_hi = -41 '\327', backend_lo = 3348, rnode = {spcNode = 12397, dbNode = 2608, relNode = 11}}, rm = {id = -5 '\373', dbId = 12397}, sn = {id = -5 '\373', dbId = 12397, relId = 2608}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 167949}, cat = {id = -2 '\376', dbId = 12397, catId = 167949}, rc = {id = -2 '\376', dbId = 12397, relId = 167949}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 167949, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 167949}}, {id = -3 '\375', cc = {id = -3 '\375', dbId = 1663, hashValue = 12397}, cat = {id = -3 '\375', dbId = 1663, catId = 12397}, rc = {id = -3 '\375', dbId = 1663, relId = 12397}, sm = {id = -3 '\375', backend_hi = -1 '\377', backend_lo = 65535, rnode = {spcNode = 1663, dbNode = 12397, relNode = 167943}}, rm = {id = -3 '\375', dbId = 1663}, sn = {id = -3 '\375', dbId = 1663, relId = 12397}}, {id = -3 '\375', cc = {id = -3 '\375', dbId = 1663, hashValue = 12397}, cat = {id = -3 '\375', dbId = 1663, catId = 12397}, rc = {id = -3 '\375', dbId = 1663, relId = 12397}, sm = {id = -3 '\375', backend_hi = -1 '\377', backend_lo = 65535, rnode = {spcNode = 1663, dbNode = 12397, relNode = 167948}}, rm = {id = -3 '\375', dbId = 1663}, sn = {id = -3 '\375', dbId = 1663, relId = 12397}}, {id = -3 '\375', cc = {id = -3 '\375', dbId = 1663, hashValue = 12397}, cat = {id = -3 '\375', dbId = 1663, catId = 12397}, rc = {id = -3 '\375', dbId = 1663, relId = 12397}, sm = {id = -3 '\375', backend_hi = -1 '\377', backend_lo = 65535, rnode = {spcNode = 1663, dbNode = 12397, relNode = 167947}}, rm = {id = -3 '\375', dbId = 1663}, sn = {id = -3 '\375', dbId = 1663, relId = 12397}}, {id = -3 '\375', cc = {id = -3 '\375', dbId = 1663, hashValue = 12397}, cat = {id = -3 '\375', dbId = 1663, catId = 12397}, rc = {id = -3 '\375', dbId = 1663, relId = 12397}, sm = {id = -3 '\375', backend_hi = -1 '\377', backend_lo = 65535, rnode = {spcNode = 1663, dbNode = 12397, relNode = 167946}}, rm = {id = -3 '\375', dbId = 1663}, sn = {id = -3 '\375', dbId = 1663, relId = 12397}}, {id = 7 '\a', cc = {id = 7 '\a', dbId = 12397, hashValue = 1528188348}, cat = {id = 7 '\a', dbId = 12397, catId = 1528188348}, rc = {id = 7 '\a', dbId = 12397, relId = 1528188348}, sm = {id = 7 '\a', backend_hi = -10 '\366', backend_lo = 58325, rnode = {spcNode = 12397, dbNode = 1528188348, relNode = 22006}}, rm = {id = 7 '\a', dbId = 12397}, sn = {id = 7 '\a', dbId = 12397, relId = 1528188348}}, {id = 6 '\006', cc = {id = 6 '\006', dbId = 12397, hashValue = 2483940397}, cat = {id = 6 '\006', dbId = 12397, catId = 2483940397}, rc = {id = 6 '\006', dbId = 12397, relId = 2483940397}, sm = {id = 6 '\006', backend_hi = 7 '\a', backend_lo = 58326, rnode = {spcNode = 12397, dbNode = 2483940397, relNode = 22006}}, rm = {id = 6 '\006', dbId = 12397}, sn = {id = 6 '\006', dbId = 12397, relId = 2483940397}}, {id = 7 '\a', cc = {id = 7 '\a', dbId = 12397, hashValue = 37473943}, cat = {id = 7 '\a', dbId = 12397, catId = 37473943}, rc = {id = 7 '\a', dbId = 12397, relId = 37473943}, sm = {id = 7 '\a', backend_hi = -10 '\366', backend_lo = 58325, rnode = {spcNode = 12397, dbNode = 37473943, relNode = 22006}}, rm = {id = 7 '\a', dbId = 12397}, sn = {id = 7 '\a', dbId = 12397, relId = 37473943}}, {id = 6 '\006', cc = {id = 6 '\006', dbId = 12397, hashValue = 2828489776}, cat = {id = 6 '\006', dbId = 12397, catId = 2828489776}, rc = {id = 6 '\006', dbId = 12397, relId = 2828489776}, sm = {id = 6 '\006', backend_hi = 7 '\a', backend_lo = 58326, rnode = {spcNode = 12397, dbNode = 2828489776, relNode = 22006}}, rm = {id = 6 '\006', dbId = 12397}, sn = {id = 6 '\006', dbId = 12397, relId = 2828489776}}, {id = 7 '\a', cc = {id = 7 '\a', dbId = 12397, hashValue = 2277595885}, cat = {id = 7 '\a', dbId = 12397, catId = 2277595885}, rc = {id = 7 '\a', dbId = 12397, relId = 2277595885}, sm = {id = 7 '\a', backend_hi = -10 '\366', backend_lo = 58325, rnode = {spcNode = 12397, dbNode = 2277595885, relNode = 22006}}, rm = {id = 7 '\a', dbId = 12397}, sn = {id = 7 '\a', dbId = 12397, relId = 2277595885}}, {id = 6 '\006', cc = {id = 6 '\006', dbId = 12397, hashValue = 3442084044}, cat = {id = 6 '\006', dbId = 12397, catId = 3442084044}, rc = {id = 6 '\006', dbId = 12397, relId = 3442084044}, sm = {id = 6 '\006', backend_hi = 7 '\a', backend_lo = 58326, rnode = {spcNode = 12397, dbNode = 3442084044, relNode = 22006}}, rm = {id = 6 '\006', dbId = 12397}, sn = {id = 6 '\006', dbId = 12397, relId = 3442084044}}, {id = 7 '\a', cc = {id = 7 '\a', dbId = 12397, hashValue = 2945592578}, cat = {id = 7 '\a', dbId = 12397, catId = 2945592578}, rc = {id = 7 '\a', dbId = 12397, relId = 2945592578}, sm = {id = 7 '\a', backend_hi = -10 '\366', backend_lo = 58325, rnode = {spcNode = 12397, dbNode = 2945592578, relNode = 22006}}, rm = {id = 7 '\a', dbId = 12397}, sn = {id = 7 '\a', dbId = 12397, relId = 2945592578}}, {id = 6 '\006', cc = {id = 6 '\006', dbId = 12397, hashValue = 134785355}, cat = {id = 6 '\006', dbId = 12397, catId = 134785355}, rc = {id = 6 '\006', dbId = 12397, relId = 134785355}, sm = {id = 6 '\006', backend_hi = 7 '\a', backend_lo = 58326, rnode = {spcNode = 12397, dbNode = 134785355, relNode = 22006}}, rm = {id = 6 '\006', dbId = 12397}, sn = {id = 6 '\006', dbId = 12397, relId = 134785355}}, {id = 7 '\a', cc = {id = 7 '\a', dbId = 12397, hashValue = 2621623531}, cat = {id = 7 '\a', dbId = 12397, catId = 2621623531}, rc = {id = 7 '\a', dbId = 12397, relId = 2621623531}, sm = {id = 7 '\a', backend_hi = -10 '\366', backend_lo = 58325, rnode = {spcNode = 12397, dbNode = 2621623531, relNode = 22006}}, rm = {id = 7 '\a', dbId = 12397}, sn = {id = 7 '\a', dbId = 12397, relId = 2621623531}}, {id = 6 '\006', cc = {id = 6 '\006', dbId = 12397, hashValue = 3549520513}, cat = {id = 6 '\006', dbId = 12397, catId = 3549520513}, rc = {id = 6 '\006', dbId = 12397, relId = 3549520513}, sm = {id = 6 '\006', backend_hi = 7 '\a', backend_lo = 58326, rnode = {spcNode = 12397, dbNode = 3549520513, relNode = 22006}}, rm = {id = 6 '\006', dbId = 12397}, sn = {id = 6 '\006', dbId = 12397, relId = 3549520513}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 167949}, cat = {id = -2 '\376', dbId = 12397, catId = 167949}, rc = {id = -2 '\376', dbId = 12397, relId = 167949}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 167949, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 167949}}, {id = -5 '\373', cc = {id = -5 '\373', dbId = 12397, hashValue = 2608}, cat = {id = -5 '\373', dbId = 12397, catId = 2608}, rc = {id = -5 '\373', dbId = 12397, relId = 2608}, sm = {id = -5 '\373', backend_hi = -37 '\333', backend_lo = 3348, rnode = {spcNode = 12397, dbNode = 2608, relNode = 11}}, rm = {id = -5 '\373', dbId = 12397}, sn = {id = -5 '\373', dbId = 12397, relId = 2608}}} nextmsg = 1 nummsgs = 20 __func__ = "ReceiveSharedInvalidMessages" #35 0x000055f6e5729223 in AcceptInvalidationMessages () at /home/andres/src/postgresql/src/backend/utils/cache/inval.c:681 No locals. #36 0x000055f6e55b6825 in LockRelationOid (relid=1259, lockmode=1) at /home/andres/src/postgresql/src/backend/storage/lmgr/lmgr.c:125 tag = {locktag_field1 = 12397, locktag_field2 = 1259, locktag_field3 = 0, locktag_field4 = 0, locktag_type = 0 '\000', locktag_lockmethodid = 1 '\001'} res = LOCKACQUIRE_OK #37 0x000055f6e51e11f8 in relation_open (relationId=1259, lockmode=1) at /home/andres/src/postgresql/src/backend/access/heap/heapam.c:1132 r = 0x55f6e5750d79 <fmgr_info+41> __func__ = "relation_open" #38 0x000055f6e51e14bd in heap_open (relationId=1259, lockmode=1) at /home/andres/src/postgresql/src/backend/access/heap/heapam.c:1298 r = 0xb8e74132f0 __func__ = "heap_open" #39 0x000055f6e57331d6 in ScanPgRelation (targetRelId=16386, indexOK=true, force_non_historic=false) at /home/andres/src/postgresql/src/backend/utils/cache/relcache.c:341 pg_class_tuple = 0x0 pg_class_desc = 0x55f6e7415350 pg_class_scan = 0x55f6e74142d0 key = {{sk_flags = 0, sk_attno = -2, sk_strategy = 3, sk_subtype = 0, sk_collation = 100, sk_func = {fn_addr = 0x55f6e569cbf8 <oideq>, fn_oid = 184, fn_nargs = 2, fn_strict = true, fn_retset = false, fn_stats = 2 '\002', fn_extra = 0x0, fn_mcxt = 0x55f6e743c570, fn_expr = 0x0}, sk_argument = 16386}} snapshot = 0x10 __func__ = "ScanPgRelation" #40 0x000055f6e5734b6f in RelationBuildDesc (targetRelId=16386, insertIt=false) at /home/andres/src/postgresql/src/backend/utils/cache/relcache.c:1082 relation = 0x0 relid = 32525 pg_class_tuple = 0x55f6e5aae2c0 <TopTransactionStateData> relp = 0x55f6e7415360 __func__ = "RelationBuildDesc" #41 0x000055f6e5737557 in RelationClearRelation (relation=0x7f0de3d56980, rebuild=true) at /home/andres/src/postgresql/src/backend/utils/cache/relcache.c:2446 save_relid = 16386 keep_tupdesc = false keep_partkey = 246 newrel = 0x55f6e73f0900 keep_rules = false keep_policies = 85 keep_partdesc = 231 __func__ = "RelationClearRelation" #42 0x000055f6e5737aaf in RelationFlushRelation (relation=0x7f0de3d56980) at /home/andres/src/postgresql/src/backend/utils/cache/relcache.c:2584 rebuild = true #43 0x000055f6e5737bc8 in RelationCacheInvalidateEntry (relationId=16386) at /home/andres/src/postgresql/src/backend/utils/cache/relcache.c:2636 relation = 0x7f0de3d56980 #44 0x000055f6e5728fe4 in LocalExecuteInvalidationMessage (msg=0x7ffc0d14dc70) at /home/andres/src/postgresql/src/backend/utils/cache/inval.c:587 i = 9 __func__ = "LocalExecuteInvalidationMessage" #45 0x000055f6e55b27c0 in ReceiveSharedInvalidMessages (invalFunction=0x55f6e5728edd <LocalExecuteInvalidationMessage>, resetFunction=0x55f6e5729149 <InvalidateSystemCaches>) at /home/andres/src/postgresql/src/backend/storage/ipc/sinval.c:121 msg = {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 16386}, cat = {id = -2 '\376', dbId = 12397, catId = 16386}, rc = {id = -2 '\376', dbId = 12397, relId = 16386}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 16386, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 16386}} getResult = 9 messages = {{id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 1259}, cat = {id = -2 '\376', dbId = 12397, catId = 1259}, rc = {id = -2 '\376', dbId = 12397, relId = 1259}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 1259, relNode = 22006}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 1259}}, {id = -5 '\373', cc = {id = -5 '\373', dbId = 12397, hashValue = 2608}, cat = {id = -5 '\373', dbId = 12397, catId = 2608}, rc = {id = -5 '\373', dbId = 12397, relId = 2608}, sm = {id = -5 '\373', backend_hi = -37 '\333', backend_lo = 3348, rnode = {spcNode = 12397, dbNode = 2608, relNode = 11}}, rm = {id = -5 '\373', dbId = 12397}, sn = {id = -5 '\373', dbId = 12397, relId = 2608}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 1259}, cat = {id = -2 '\376', dbId = 12397, catId = 1259}, rc = {id = -2 '\376', dbId = 12397, relId = 1259}, sm = {id = -2 '\376', backend_hi = -38 '\332', backend_lo = 3348, rnode = {spcNode = 12397, dbNode = 1259, relNode = 22006}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 1259}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 3455}, cat = {id = -2 '\376', dbId = 12397, catId = 3455}, rc = {id = -2 '\376', dbId = 12397, relId = 3455}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 3455, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 3455}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 3455}, cat = {id = -2 '\376', dbId = 12397, catId = 3455}, rc = {id = -2 '\376', dbId = 12397, relId = 3455}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 3455, relNode = 22006}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 3455}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 1259}, cat = {id = -2 '\376', dbId = 12397, catId = 1259}, rc = {id = -2 '\376', dbId = 12397, relId = 1259}, sm = {id = -2 '\376', backend_hi = -38 '\332', backend_lo = 3348, rnode = {spcNode = 12397, dbNode = 1259, relNode = 22006}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 1259}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 2663}, cat = {id = -2 '\376', dbId = 12397, catId = 2663}, rc = {id = -2 '\376', dbId = 12397, relId = 2663}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 2663, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 2663}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 2663}, cat = {id = -2 '\376', dbId = 12397, catId = 2663}, rc = {id = -2 '\376', dbId = 12397, relId = 2663}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 2663, relNode = 22006}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 2663}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 1259}, cat = {id = -2 '\376', dbId = 12397, catId = 1259}, rc = {id = -2 '\376', dbId = 12397, relId = 1259}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 1259, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 1259}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 2662}, cat = {id = -2 '\376', dbId = 12397, catId = 2662}, rc = {id = -2 '\376', dbId = 12397, relId = 2662}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 2662, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 2662}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 2662}, cat = {id = -2 '\376', dbId = 12397, catId = 2662}, rc = {id = -2 '\376', dbId = 12397, relId = 2662}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 2662, relNode = 22006}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 2662}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 1259}, cat = {id = -2 '\376', dbId = 12397, catId = 1259}, rc = {id = -2 '\376', dbId = 12397, relId = 1259}, sm = {id = -2 '\376', backend_hi = 0 '\000', backend_lo = 0, rnode = {spcNode = 12397, dbNode = 1259, relNode = 32525}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 1259}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 167949}, cat = {id = -2 '\376', dbId = 12397, catId = 167949}, rc = {id = -2 '\376', dbId = 12397, relId = 167949}, sm = {id = -2 '\376', backend_hi = 0 '\000', backend_lo = 0, rnode = {spcNode = 12397, dbNode = 167949, relNode = 11}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 167949}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 167949}, cat = {id = -2 '\376', dbId = 12397, catId = 167949}, rc = {id = -2 '\376', dbId = 12397, relId = 167949}, sm = {id = -2 '\376', backend_hi = 0 '\000', backend_lo = 0, rnode = {spcNode = 12397, dbNode = 167949, relNode = 32525}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 167949}}, {id = -5 '\373', cc = {id = -5 '\373', dbId = 12397, hashValue = 2608}, cat = {id = -5 '\373', dbId = 12397, catId = 2608}, rc = {id = -5 '\373', dbId = 12397, relId = 2608}, sm = {id = -5 '\373', backend_hi = -41 '\327', backend_lo = 3348, rnode = {spcNode = 12397, dbNode = 2608, relNode = 11}}, rm = {id = -5 '\373', dbId = 12397}, sn = {id = -5 '\373', dbId = 12397, relId = 2608}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 167949}, cat = {id = -2 '\376', dbId = 12397, catId = 167949}, rc = {id = -2 '\376', dbId = 12397, relId = 167949}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 167949, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 167949}}, {id = -3 '\375', cc = {id = -3 '\375', dbId = 1663, hashValue = 12397}, cat = {id = -3 '\375', dbId = 1663, catId = 12397}, rc = {id = -3 '\375', dbId = 1663, relId = 12397}, sm = {id = -3 '\375', backend_hi = -1 '\377', backend_lo = 65535, rnode = {spcNode = 1663, dbNode = 12397, relNode = 167943}}, rm = {id = -3 '\375', dbId = 1663}, sn = {id = -3 '\375', dbId = 1663, relId = 12397}}, {id = -3 '\375', cc = {id = -3 '\375', dbId = 1663, hashValue = 12397}, cat = {id = -3 '\375', dbId = 1663, catId = 12397}, rc = {id = -3 '\375', dbId = 1663, relId = 12397}, sm = {id = -3 '\375', backend_hi = -1 '\377', backend_lo = 65535, rnode = {spcNode = 1663, dbNode = 12397, relNode = 167948}}, rm = {id = -3 '\375', dbId = 1663}, sn = {id = -3 '\375', dbId = 1663, relId = 12397}}, {id = -3 '\375', cc = {id = -3 '\375', dbId = 1663, hashValue = 12397}, cat = {id = -3 '\375', dbId = 1663, catId = 12397}, rc = {id = -3 '\375', dbId = 1663, relId = 12397}, sm = {id = -3 '\375', backend_hi = -1 '\377', backend_lo = 65535, rnode = {spcNode = 1663, dbNode = 12397, relNode = 167947}}, rm = {id = -3 '\375', dbId = 1663}, sn = {id = -3 '\375', dbId = 1663, relId = 12397}}, {id = -3 '\375', cc = {id = -3 '\375', dbId = 1663, hashValue = 12397}, cat = {id = -3 '\375', dbId = 1663, catId = 12397}, rc = {id = -3 '\375', dbId = 1663, relId = 12397}, sm = {id = -3 '\375', backend_hi = -1 '\377', backend_lo = 65535, rnode = {spcNode = 1663, dbNode = 12397, relNode = 167946}}, rm = {id = -3 '\375', dbId = 1663}, sn = {id = -3 '\375', dbId = 1663, relId = 12397}}, {id = 7 '\a', cc = {id = 7 '\a', dbId = 12397, hashValue = 1528188348}, cat = {id = 7 '\a', dbId = 12397, catId = 1528188348}, rc = {id = 7 '\a', dbId = 12397, relId = 1528188348}, sm = {id = 7 '\a', backend_hi = -10 '\366', backend_lo = 58325, rnode = {spcNode = 12397, dbNode = 1528188348, relNode = 22006}}, rm = {id = 7 '\a', dbId = 12397}, sn = {id = 7 '\a', dbId = 12397, relId = 1528188348}}, {id = 6 '\006', cc = {id = 6 '\006', dbId = 12397, hashValue = 2483940397}, cat = {id = 6 '\006', dbId = 12397, catId = 2483940397}, rc = {id = 6 '\006', dbId = 12397, relId = 2483940397}, sm = {id = 6 '\006', backend_hi = 7 '\a', backend_lo = 58326, rnode = {spcNode = 12397, dbNode = 2483940397, relNode = 22006}}, rm = {id = 6 '\006', dbId = 12397}, sn = {id = 6 '\006', dbId = 12397, relId = 2483940397}}, {id = 7 '\a', cc = {id = 7 '\a', dbId = 12397, hashValue = 37473943}, cat = {id = 7 '\a', dbId = 12397, catId = 37473943}, rc = {id = 7 '\a', dbId = 12397, relId = 37473943}, sm = {id = 7 '\a', backend_hi = -10 '\366', backend_lo = 58325, rnode = {spcNode = 12397, dbNode = 37473943, relNode = 22006}}, rm = {id = 7 '\a', dbId = 12397}, sn = {id = 7 '\a', dbId = 12397, relId = 37473943}}, {id = 6 '\006', cc = {id = 6 '\006', dbId = 12397, hashValue = 2828489776}, cat = {id = 6 '\006', dbId = 12397, catId = 2828489776}, rc = {id = 6 '\006', dbId = 12397, relId = 2828489776}, sm = {id = 6 '\006', backend_hi = 7 '\a', backend_lo = 58326, rnode = {spcNode = 12397, dbNode = 2828489776, relNode = 22006}}, rm = {id = 6 '\006', dbId = 12397}, sn = {id = 6 '\006', dbId = 12397, relId = 2828489776}}, {id = 7 '\a', cc = {id = 7 '\a', dbId = 12397, hashValue = 2277595885}, cat = {id = 7 '\a', dbId = 12397, catId = 2277595885}, rc = {id = 7 '\a', dbId = 12397, relId = 2277595885}, sm = {id = 7 '\a', backend_hi = -10 '\366', backend_lo = 58325, rnode = {spcNode = 12397, dbNode = 2277595885, relNode = 22006}}, rm = {id = 7 '\a', dbId = 12397}, sn = {id = 7 '\a', dbId = 12397, relId = 2277595885}}, {id = 6 '\006', cc = {id = 6 '\006', dbId = 12397, hashValue = 3442084044}, cat = {id = 6 '\006', dbId = 12397, catId = 3442084044}, rc = {id = 6 '\006', dbId = 12397, relId = 3442084044}, sm = {id = 6 '\006', backend_hi = 7 '\a', backend_lo = 58326, rnode = {spcNode = 12397, dbNode = 3442084044, relNode = 22006}}, rm = {id = 6 '\006', dbId = 12397}, sn = {id = 6 '\006', dbId = 12397, relId = 3442084044}}, {id = 7 '\a', cc = {id = 7 '\a', dbId = 12397, hashValue = 2945592578}, cat = {id = 7 '\a', dbId = 12397, catId = 2945592578}, rc = {id = 7 '\a', dbId = 12397, relId = 2945592578}, sm = {id = 7 '\a', backend_hi = -10 '\366', backend_lo = 58325, rnode = {spcNode = 12397, dbNode = 2945592578, relNode = 22006}}, rm = {id = 7 '\a', dbId = 12397}, sn = {id = 7 '\a', dbId = 12397, relId = 2945592578}}, {id = 6 '\006', cc = {id = 6 '\006', dbId = 12397, hashValue = 134785355}, cat = {id = 6 '\006', dbId = 12397, catId = 134785355}, rc = {id = 6 '\006', dbId = 12397, relId = 134785355}, sm = {id = 6 '\006', backend_hi = 7 '\a', backend_lo = 58326, rnode = {spcNode = 12397, dbNode = 134785355, relNode = 22006}}, rm = {id = 6 '\006', dbId = 12397}, sn = {id = 6 '\006', dbId = 12397, relId = 134785355}}, {id = 7 '\a', cc = {id = 7 '\a', dbId = 12397, hashValue = 2621623531}, cat = {id = 7 '\a', dbId = 12397, catId = 2621623531}, rc = {id = 7 '\a', dbId = 12397, relId = 2621623531}, sm = {id = 7 '\a', backend_hi = -10 '\366', backend_lo = 58325, rnode = {spcNode = 12397, dbNode = 2621623531, relNode = 22006}}, rm = {id = 7 '\a', dbId = 12397}, sn = {id = 7 '\a', dbId = 12397, relId = 2621623531}}, {id = 6 '\006', cc = {id = 6 '\006', dbId = 12397, hashValue = 3549520513}, cat = {id = 6 '\006', dbId = 12397, catId = 3549520513}, rc = {id = 6 '\006', dbId = 12397, relId = 3549520513}, sm = {id = 6 '\006', backend_hi = 7 '\a', backend_lo = 58326, rnode = {spcNode = 12397, dbNode = 3549520513, relNode = 22006}}, rm = {id = 6 '\006', dbId = 12397}, sn = {id = 6 '\006', dbId = 12397, relId = 3549520513}}, {id = -2 '\376', cc = {id = -2 '\376', dbId = 12397, hashValue = 167949}, cat = {id = -2 '\376', dbId = 12397, catId = 167949}, rc = {id = -2 '\376', dbId = 12397, relId = 167949}, sm = {id = -2 '\376', backend_hi = -114 '\216', backend_lo = 58738, rnode = {spcNode = 12397, dbNode = 167949, relNode = 0}}, rm = {id = -2 '\376', dbId = 12397}, sn = {id = -2 '\376', dbId = 12397, relId = 167949}}, {id = -5 '\373', cc = {id = -5 '\373', dbId = 12397, hashValue = 2608}, cat = {id = -5 '\373', dbId = 12397, catId = 2608}, rc = {id = -5 '\373', dbId = 12397, relId = 2608}, sm = {id = -5 '\373', backend_hi = -37 '\333', backend_lo = 3348, rnode = {spcNode = 12397, dbNode = 2608, relNode = 11}}, rm = {id = -5 '\373', dbId = 12397}, sn = {id = -5 '\373', dbId = 12397, relId = 2608}}} nextmsg = 1 nummsgs = 20 __func__ = "ReceiveSharedInvalidMessages" #46 0x000055f6e5729223 in AcceptInvalidationMessages () at /home/andres/src/postgresql/src/backend/utils/cache/inval.c:681 No locals. #47 0x000055f6e55b6825 in LockRelationOid (relid=16384, lockmode=3) at /home/andres/src/postgresql/src/backend/storage/lmgr/lmgr.c:125 tag = {locktag_field1 = 12397, locktag_field2 = 16384, locktag_field3 = 0, locktag_field4 = 0, locktag_type = 0 '\000', locktag_lockmethodid = 1 '\001'} res = LOCKACQUIRE_OK #48 0x000055f6e5386187 in lock_and_open_sequence (seq=0x55f6e743fed0) at /home/andres/src/postgresql/src/backend/commands/sequence.c:1059 currentOwner = 0x55f6e73b0990 thislxid = 200412 #49 0x000055f6e538629e in init_sequence (relid=16384, p_elm=0x7ffc0d14de38, p_rel=0x7ffc0d14de30) at /home/andres/src/postgresql/src/backend/commands/sequence.c:1124 elm = 0x55f6e743fed0 seqrel = 0x60 found = true __func__ = "init_sequence" #50 0x000055f6e5385032 in nextval_internal (relid=16384, check_permissions=true) at /home/andres/src/postgresql/src/backend/commands/sequence.c:592 elm = 0x55f6e577962e <AllocSetAlloc+698> seqrel = 0x7ffc0d14e0a0 buf = 0 page = 0x4d430000 <error: Cannot access memory at address 0x4d430000> pgstuple = 0x55f6e5723c42 <int4hashfast+23> pgsform = 0x7ffc0d14dea0 seqdatatuple = {t_len = 16, t_self = {ip_blkid = {bi_hi = 0, bi_lo = 0}, ip_posid = 42336}, t_tableOid = 22006, t_data = 0x0} seq = 0x55f6e743ac78 incby = -3334848951855292406 maxv = 94518896342214 minv = 99003719328 cache = 94518930289304 log = 94518929721808 fetch = 139697633736304 last = 94518929721808 result = 23 next = 94518899785832 rescnt = 0 cycle = false logit = false __func__ = "nextval_internal" #51 0x000055f6e5384fec in nextval_oid (fcinfo=0x55f6e743b810) at /home/andres/src/postgresql/src/backend/commands/sequence.c:564 relid = 16384 #52 0x000055f6e53de11b in ExecInterpExpr (state=0x55f6e743b2b8, econtext=0x55f6e743af08, isnull=0x7ffc0d14e1d7) at /home/andres/src/postgresql/src/backend/executor/execExprInterp.c:678 fcinfo = 0x55f6e743b810 argnull = 0x55f6e743bb50 argno = 1 d = 94518903500096 op = 0x55f6e743bc28 resultslot = 0x55f6e743b1b8 innerslot = 0x0 outerslot = 0x0 scanslot = 0x0 dispatch_table = {0x55f6e53dd811 <ExecInterpExpr+148>, 0x55f6e53dd838 <ExecInterpExpr+187>, 0x55f6e53dd85b <ExecInterpExpr+222>, 0x55f6e53dd87e <ExecInterpExpr+257>, 0x55f6e53dd8a1 <ExecInterpExpr+292>, 0x55f6e53dd92e <ExecInterpExpr+433>, 0x55f6e53dd9bb <ExecInterpExpr+574>, 0x55f6e53dda48 <ExecInterpExpr+715>, 0x55f6e53ddaf9 <ExecInterpExpr+892>, 0x55f6e53ddbaa <ExecInterpExpr+1069>, 0x55f6e53ddc67 <ExecInterpExpr+1258>, 0x55f6e53ddc95 <ExecInterpExpr+1304>, 0x55f6e53ddd5a <ExecInterpExpr+1501>, 0x55f6e53dde1f <ExecInterpExpr+1698>, 0x55f6e53ddee4 <ExecInterpExpr+1895>, 0x55f6e53ddf48 <ExecInterpExpr+1995>, 0x55f6e53ddffa <ExecInterpExpr+2173>, 0x55f6e53de030 <ExecInterpExpr+2227>, 0x55f6e53de09d <ExecInterpExpr+2336>, 0x55f6e53de15a <ExecInterpExpr+2525>, 0x55f6e53de188 <ExecInterpExpr+2571>, 0x55f6e53de1b6 <ExecInterpExpr+2617>, 0x55f6e53de1c1 <ExecInterpExpr+2628>, 0x55f6e53de229 <ExecInterpExpr+2732>, 0x55f6e53de282 <ExecInterpExpr+2821>, 0x55f6e53de28d <ExecInterpExpr+2832>, 0x55f6e53de2f5 <ExecInterpExpr+2936>, 0x55f6e53de34e <ExecInterpExpr+3025>, 0x55f6e53de386 <ExecInterpExpr+3081>, 0x55f6e53de3fb <ExecInterpExpr+3198>, 0x55f6e53de426 <ExecInterpExpr+3241>, 0x55f6e53de471 <ExecInterpExpr+3316>, 0x55f6e53de4bf <ExecInterpExpr+3394>, 0x55f6e53de51a <ExecInterpExpr+3485>, 0x55f6e53de55c <ExecInterpExpr+3551>, 0x55f6e53de5a1 <ExecInterpExpr+3620>, 0x55f6e53de5cf <ExecInterpExpr+3666>, 0x55f6e53de5fd <ExecInterpExpr+3712>, 0x55f6e53de637 <ExecInterpExpr+3770>, 0x55f6e53de69a <ExecInterpExpr+3869>, 0x55f6e53de6fd <ExecInterpExpr+3968>, 0x55f6e53de737 <ExecInterpExpr+4026>, 0x55f6e53de765 <ExecInterpExpr+4072>, 0x55f6e53de793 <ExecInterpExpr+4118>, 0x55f6e53de7c3 <ExecInterpExpr+4166>, 0x55f6e53de8af <ExecInterpExpr+4402>, 0x55f6e53de905 <ExecInterpExpr+4488>, 0x55f6e53deb11 <ExecInterpExpr+5012>, 0x55f6e53dec10 <ExecInterpExpr+5267>, 0x55f6e53ded00 <ExecInterpExpr+5507>, 0x55f6e53dede9 <ExecInterpExpr+5740>, 0x55f6e53dee10 <ExecInterpExpr+5779>, 0x55f6e53dee37 <ExecInterpExpr+5818>, 0x55f6e53dee5e <ExecInterpExpr+5857>, 0x55f6e53dee85 <ExecInterpExpr+5896>, 0x55f6e53deeb3 <ExecInterpExpr+5942>, 0x55f6e53deeda <ExecInterpExpr+5981>, 0x55f6e53df026 <ExecInterpExpr+6313>, 0x55f6e53df13b <ExecInterpExpr+6590>, 0x55f6e53df162 <ExecInterpExpr+6629>, 0x55f6e53df190 <ExecInterpExpr+6675>, 0x55f6e53df1be <ExecInterpExpr+6721>, 0x55f6e53df1ec <ExecInterpExpr+6767>, 0x55f6e53df242 <ExecInterpExpr+6853>, 0x55f6e53df269 <ExecInterpExpr+6892>, 0x55f6e53df290 <ExecInterpExpr+6931>, 0x55f6e53de839 <ExecInterpExpr+4284>, 0x55f6e53df30c <ExecInterpExpr+7055>, 0x55f6e53df333 <ExecInterpExpr+7094>, 0x55f6e53df2b7 <ExecInterpExpr+6970>, 0x55f6e53df2e5 <ExecInterpExpr+7016>, 0x55f6e53df35a <ExecInterpExpr+7133>, 0x55f6e53df381 <ExecInterpExpr+7172>, 0x55f6e53df424 <ExecInterpExpr+7335>, 0x55f6e53df44b <ExecInterpExpr+7374>, 0x55f6e53df4ee <ExecInterpExpr+7537>, 0x55f6e53df51c <ExecInterpExpr+7583>, 0x55f6e53df54a <ExecInterpExpr+7629>, 0x55f6e53df598 <ExecInterpExpr+7707>, 0x55f6e53df63b <ExecInterpExpr+7870>, 0x55f6e53df6c1 <ExecInterpExpr+8004>, 0x55f6e53df7b0 <ExecInterpExpr+8243>, 0x55f6e53df846 <ExecInterpExpr+8393>, 0x55f6e53df9e2 <ExecInterpExpr+8805>, 0x55f6e53dfbd6 <ExecInterpExpr+9305>, 0x55f6e53dfc04 <ExecInterpExpr+9351>, 0x55f6e53dfc32 <ExecInterpExpr+9397>} #53 0x000055f6e53dfcae in ExecInterpExprStillValid (state=0x55f6e743b2b8, econtext=0x55f6e743af08, isNull=0x7ffc0d14e1d7) at /home/andres/src/postgresql/src/backend/executor/execExprInterp.c:1786 No locals. #54 0x000055f6e542225e in ExecEvalExprSwitchContext (state=0x55f6e743b2b8, econtext=0x55f6e743af08, isNull=0x7ffc0d14e1d7) at /home/andres/src/postgresql/src/include/executor/executor.h:303 retDatum = 128 oldContext = 0x55f6e743a560 #55 0x000055f6e54222c7 in ExecProject (projInfo=0x55f6e743b2b0) at /home/andres/src/postgresql/src/include/executor/executor.h:337 econtext = 0x55f6e743af08 state = 0x55f6e743b2b8 slot = 0x55f6e743b1b8 isnull = false #56 0x000055f6e542249e in ExecResult (pstate=0x55f6e743adf0) at /home/andres/src/postgresql/src/backend/executor/nodeResult.c:136 node = 0x55f6e743adf0 outerTupleSlot = 0x940 outerPlan = 0x0 econtext = 0x55f6e743af08 #57 0x000055f6e53f2c42 in ExecProcNodeFirst (node=0x55f6e743adf0) at /home/andres/src/postgresql/src/backend/executor/execProcnode.c:445 No locals. #58 0x000055f6e541c327 in ExecProcNode (node=0x55f6e743adf0) at /home/andres/src/postgresql/src/include/executor/executor.h:237 No locals. #59 0x000055f6e541f327 in ExecModifyTable (pstate=0x55f6e743a9e0) at /home/andres/src/postgresql/src/backend/executor/nodeModifyTable.c:2027 node = 0x55f6e743a9e0 proute = 0x0 estate = 0x55f6e743a678 operation = CMD_INSERT saved_resultRelInfo = 0x0 resultRelInfo = 0x55f6e743a8c8 subplanstate = 0x55f6e743adf0 junkfilter = 0x0 slot = 0x7ffc0d14e430 planSlot = 0x55f6e743a678 tupleid = 0x55f6e743c078 tuple_ctid = {ip_blkid = {bi_hi = 58687, bi_lo = 22006}, ip_posid = 0} oldtupdata = {t_len = 3846304154, t_self = {ip_blkid = {bi_hi = 22006, bi_lo = 0}, ip_posid = 0}, t_tableOid = 0, t_data = 0x7ffc0d14e320} oldtuple = 0x0 __func__ = "ExecModifyTable" #60 0x000055f6e53f2c42 in ExecProcNodeFirst (node=0x55f6e743a9e0) at /home/andres/src/postgresql/src/backend/executor/execProcnode.c:445 No locals. #61 0x000055f6e53e7aef in ExecProcNode (node=0x55f6e743a9e0) at /home/andres/src/postgresql/src/include/executor/executor.h:237 No locals. #62 0x000055f6e53ea4d9 in ExecutePlan (estate=0x55f6e743a678, planstate=0x55f6e743a9e0, use_parallel_mode=false, operation=CMD_INSERT, sendTuples=false, numberTuples=0, direction=ForwardScanDirection, dest=0x55f6e73a7678, execute_once=true) at /home/andres/src/postgresql/src/backend/executor/execMain.c:1721 slot = 0x55f6e73a73e0 current_tuple_count = 0 #63 0x000055f6e53e80f6 in standard_ExecutorRun (queryDesc=0x55f6e739ef88, direction=ForwardScanDirection, count=0, execute_once=true) at /home/andres/src/postgresql/src/backend/executor/execMain.c:362 estate = 0x55f6e743a678 operation = CMD_INSERT dest = 0x55f6e73a7678 sendTuples = false oldcontext = 0x55f6e739ee70 __func__ = "standard_ExecutorRun" #64 0x000055f6e53e7f0c in ExecutorRun (queryDesc=0x55f6e739ef88, direction=ForwardScanDirection, count=0, execute_once=true) at /home/andres/src/postgresql/src/backend/executor/execMain.c:305 No locals. #65 0x000055f6e55dd7e6 in ProcessQuery (plan=0x55f6e73a7500, sourceText=0x55f6e737d438 "insert into t (b,c) values (1,1);", params=0x0, queryEnv=0x0, dest=0x55f6e73a7678, completionTag=0x7ffc0d14e6d0 "") at /home/andres/src/postgresql/src/backend/tcop/pquery.c:161 queryDesc = 0x55f6e739ef88 #66 0x000055f6e55df188 in PortalRunMulti (portal=0x55f6e73e5038, isTopLevel=true, setHoldSnapshot=false, dest=0x55f6e73a7678, altdest=0x55f6e73a7678, completionTag=0x7ffc0d14e6d0 "") at /home/andres/src/postgresql/src/backend/tcop/pquery.c:1286 pstmt = 0x55f6e73a7500 active_snapshot_set = true stmtlist_item = 0x55f6e73a7618 #67 0x000055f6e55de742 in PortalRun (portal=0x55f6e73e5038, count=9223372036854775807, isTopLevel=true, run_once=true, dest=0x55f6e73a7678, altdest=0x55f6e73a7678, completionTag=0x7ffc0d14e6d0 "") at /home/andres/src/postgresql/src/backend/tcop/pquery.c:799 save_exception_stack = 0x7ffc0d14e810 save_context_stack = 0x0 local_sigjmp_buf = {{__jmpbuf = {0, 2133478022532337521, 94518893857616, 140720527961408, 0, 0, 2133478022492491633, 5300299599030161265}, __mask_was_saved = 0, __saved_mask = {__val = {94518900186830, 94518929721744, 112, 4869, 94518929511200, 94518929684088, 112, 0, 0, 94518929948024, 0, 94518929684200, 112, 219473504, 94518929684088, 94518929511200}}}} result = false nprocessed = 0 saveTopTransactionResourceOwner = 0x55f6e73ad0e8 saveTopTransactionContext = 0x55f6e7403af0 saveActivePortal = 0x0 saveResourceOwner = 0x55f6e73ad0e8 savePortalContext = 0x0 saveMemoryContext = 0x55f6e7403af0 __func__ = "PortalRun" #68 0x000055f6e55d82fd in exec_simple_query (query_string=0x55f6e737d438 "insert into t (b,c) values (1,1);") at /home/andres/src/postgresql/src/backend/tcop/postgres.c:1122 parsetree = 0x55f6e737e308 portal = 0x55f6e73e5038 snapshot_set = true commandTag = 0x55f6e5971820 "INSERT" completionTag = "\000\000\000\000\002\000\000\000\034\071v\345\366U\000\000\000\000\000\000\000\000\000\000P\330\067\347!\000\000\000 \347\024\r\374\177\000\000o@v\345\366U\000\000`\347\024\r\004\000\000\000\000\000\000\000\000\000\000" querytree_list = 0x55f6e737f098 plantree_list = 0x55f6e73a7640 receiver = 0x55f6e73a7678 format = 0 dest = DestRemote oldcontext = 0x55f6e7403af0 parsetree_list = 0x55f6e737e368 parsetree_item = 0x55f6e737e340 save_log_statement_stats = false was_logged = false use_implicit_block = false msec_str = "`\347\024\r\374\177\000\000\005\017v\345\366U\000\000\006\000\000\000!\000\000\000\070\324\067\347\366U\000" __func__ = "exec_simple_query" #69 0x000055f6e55dc8ab in PostgresMain (argc=1, argv=0x55f6e73ab648, dbname=0x55f6e73ab540 "postgres", username=0x55f6e73ab520 "andres") at /home/andres/src/postgresql/src/backend/tcop/postgres.c:4159 query_string = 0x55f6e737d438 "insert into t (b,c) values (1,1);" firstchar = 81 input_message = {data = 0x55f6e737d438 "insert into t (b,c) values (1,1);", len = 34, maxlen = 1024, cursor = 34} local_sigjmp_buf = {{__jmpbuf = {0, 2133478022354079601, 94518893857616, 140720527961408, 0, 0, 2133478022576377713, 5300299600075067249}, __mask_was_saved = 1, __saved_mask = {__val = {0, 16, 0, 0, 0, 4869, 0, 33943971976, 94518929516680, 94518929516656, 94518929511200, 140720527960336, 94518900188034, 94518929516680, 94518929516680, 4870}}}} send_ready_for_query = false disable_idle_in_transaction_timeout = false __func__ = "PostgresMain" #70 0x000055f6e5535ce4 in BackendRun (port=0x55f6e73a10b0) at /home/andres/src/postgresql/src/backend/postmaster/postmaster.c:4361 av = 0x55f6e73ab648 maxac = 2 ac = 1 secs = 587288130 usecs = 313711 i = 1 __func__ = "BackendRun" #71 0x000055f6e55353df in BackendStartup (port=0x55f6e73a10b0) at /home/andres/src/postgresql/src/backend/postmaster/postmaster.c:4033 bn = 0x55f6e73a0510 pid = 0 __func__ = "BackendStartup" #72 0x000055f6e5531674 in ServerLoop () at /home/andres/src/postgresql/src/backend/postmaster/postmaster.c:1706 port = 0x55f6e73a10b0 i = 1 rmask = {fds_bits = {16, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0}} selres = 1 now = 1533972930 readmask = {fds_bits = {24, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0}} nSockets = 5 last_lockfile_recheck_time = 1533972883 last_touch_time = 1533971868 __func__ = "ServerLoop" #73 0x000055f6e5530ea6 in PostmasterMain (argc=45, argv=0x55f6e7377340) at /home/andres/src/postgresql/src/backend/postmaster/postmaster.c:1379 opt = -1 status = 0 userDoption = 0x55f6e7399e50 "/srv/dev/pgdev-dev/" listen_addr_saved = true i = 64 output_config_variable = 0x0 __func__ = "PostmasterMain" #74 0x000055f6e5456112 in main (argc=45, argv=0x55f6e7377340) at /home/andres/src/postgresql/src/backend/main/main.c:228 do_check_root = true Greetings, Andres Freund -
Re: logical decoding / rewrite map vs. maxAllocatedDescs
Andres Freund <andres@anarazel.de> — 2018-08-11T07:57:56Z
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
-
Re: logical decoding / rewrite map vs. maxAllocatedDescs
Tomas Vondra <tomas.vondra@2ndquadrant.com> — 2018-08-11T13:11:19Z
On 08/11/2018 09:34 AM, Andres Freund wrote: > Hi, > > On 2018-08-11 01:55:43 +0200, Tomas Vondra wrote: >> On 08/10/2018 11:59 PM, Tomas Vondra wrote: >>> >>> ... >>> >>> I suspect there's some other ingredient, e.g. some manipulation with the >>> subscription. Or maybe it's not needed at all and I'm just imagining things. >>> >> >> Indeed, the manipulation with the subscription seems to be the key here. >> I pretty reliably get the 'could not read block' error when doing this: >> >> 1) start the insert pgbench >> >> pgbench -n -c 4 -T 300 -p 5433 -f insert.sql test >> >> 2) start the vacuum full pgbench >> >> pgbench -n -f vacuum.sql -T 300 -p 5433 test > > Just to be clear: 5433 is the subscriber, right? I tried it with both, > but it's not clear what you meant with either the previous or the this > email. > Sorry for the confusion, 5433 was the publisher - I reinitialized the cluster sometime after the initial report, and happened to swap the port numbers. That is, both pgbench commands run on the publisher, while the subscriber tries to sync the table (and fails due to duplicate values). I can reproduce it pretty reliably, although it may take a couple of sync tries from the subscriber. regards -- Tomas Vondra http://www.2ndQuadrant.com PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
-
Re: logical decoding / rewrite map vs. maxAllocatedDescs
Tomas Vondra <tomas.vondra@2ndquadrant.com> — 2018-08-11T13:14:59Z
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
-
Re: logical decoding / rewrite map vs. maxAllocatedDescs
Tomas Vondra <tomas.vondra@2ndquadrant.com> — 2018-08-11T13:43:55Z
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
-
Re: logical decoding / rewrite map vs. maxAllocatedDescs
Tom Lane <tgl@sss.pgh.pa.us> — 2018-08-11T14:15:56Z
Tomas Vondra <tomas.vondra@2ndquadrant.com> writes: >>> On 08/09/2018 07:47 PM, Alvaro Herrera wrote: >>>> Actually, it seems to me that ApplyLogicalMappingFile is just leaking >>>> the file descriptor for no good reason. > I think the fix can be as simple as attached ... I'm mostly afk for the > weekend, so I'll commit & backpatch on Monday or so. LGTM. While you're at it, would you fix the misspelling three lines below this? * Check whether the TransactionOId 'xid' is in the pre-sorted array 'xip'. ^ regards, tom lane -
Re: logical decoding / rewrite map vs. maxAllocatedDescs
Tomas Vondra <tomas.vondra@2ndquadrant.com> — 2018-08-11T14:18:20Z
On 08/11/2018 04:15 PM, Tom Lane wrote: > Tomas Vondra <tomas.vondra@2ndquadrant.com> writes: >>>> On 08/09/2018 07:47 PM, Alvaro Herrera wrote: >>>>> Actually, it seems to me that ApplyLogicalMappingFile is just leaking >>>>> the file descriptor for no good reason. > >> I think the fix can be as simple as attached ... I'm mostly afk for the >> weekend, so I'll commit & backpatch on Monday or so. > > LGTM. While you're at it, would you fix the misspelling three lines > below this? > > * Check whether the TransactionOId 'xid' is in the pre-sorted array 'xip'. > ^ > Sure. -- Tomas Vondra http://www.2ndQuadrant.com PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
-
Re: logical decoding / rewrite map vs. maxAllocatedDescs
Alvaro Herrera <alvherre@2ndquadrant.com> — 2018-08-13T14:46:30Z
On 2018-Aug-11, Tomas Vondra wrote: > Hmmm, it's difficult to compare "bt full" output, but my backtraces look > somewhat different (and all the backtraces I'm seeing are 100% exactly > the same). Attached for comparison. Hmm, looks similar enough to me -- at the bottom you have the executor doing its thing, then an AcceptInvalidationMessages in the middle section atop which sit a few more catalog accesses, and further up from that you have another AcceptInvalidationMessages with more catalog accesses. AFAICS that's pretty much the same thing Andres was describing. I think the exact shape of the executor bits is not relevant, and I suppose the exact details of what occurs when invalidation messages are processed are not terribly important either. I think in Andres' backtrace there are *three* AcceptInvalidationMessages rather than two as in your case, but that shouldn't be important either, just the fact that there are N nested ones. -- Álvaro Herrera https://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
-
Re: logical decoding / rewrite map vs. maxAllocatedDescs
Andres Freund <andres@anarazel.de> — 2018-08-13T14:49:46Z
Hi, On 2018-08-13 11:46:30 -0300, Alvaro Herrera wrote: > On 2018-Aug-11, Tomas Vondra wrote: > > > Hmmm, it's difficult to compare "bt full" output, but my backtraces look > > somewhat different (and all the backtraces I'm seeing are 100% exactly > > the same). Attached for comparison. > > Hmm, looks similar enough to me -- at the bottom you have the executor > doing its thing, then an AcceptInvalidationMessages in the middle > section atop which sit a few more catalog accesses, and further up from > that you have another AcceptInvalidationMessages with more catalog > accesses. AFAICS that's pretty much the same thing Andres was > describing. It's somewhat different because it doesn't seem to involve a reload of a nailed table, which my traces did. I wasn't able to reproduce the crash more than once, so I'm not at all sure how to properly verify the issue. I'd appreciate if Thomas could try to do so again with the small patch I provided. Greetings, Andres Freund
-
Re: logical decoding / rewrite map vs. maxAllocatedDescs
Alvaro Herrera <alvherre@2ndquadrant.com> — 2018-08-13T14:50:41Z
On 2018-Aug-11, Andres Freund wrote: > On 2018-08-11 00:46:25 -0700, Andres Freund wrote: > > Below you can find the bt full showing a bunch of nested invalidations. Looking. > > Hm. I wonder if the attached fixes the issue for you. If it's this I > don't understand why this doesn't occur on older branches... > > I've not yet been able to reliably reproduce the issue without the > patch, so I'm not sure it means much that it didn't reoccur afterwards. Well, the line you're patching was introduced in 2ce64caaf793 (looking at pg10), and was not replacing a line with the exact same mistake. -- Álvaro Herrera https://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
-
Re: logical decoding / rewrite map vs. maxAllocatedDescs
Andres Freund <andres@anarazel.de> — 2018-08-13T14:54:05Z
On 2018-08-13 11:50:41 -0300, Alvaro Herrera wrote: > On 2018-Aug-11, Andres Freund wrote: > > > On 2018-08-11 00:46:25 -0700, Andres Freund wrote: > > > Below you can find the bt full showing a bunch of nested invalidations. Looking. > > > > Hm. I wonder if the attached fixes the issue for you. If it's this I > > don't understand why this doesn't occur on older branches... > > > > I've not yet been able to reliably reproduce the issue without the > > patch, so I'm not sure it means much that it didn't reoccur afterwards. > > Well, the line you're patching was introduced in 2ce64caaf793 (looking > at pg10), and was not replacing a line with the exact same mistake. I'm not clear on what you're trying to say? My problem is that Thomas' backtraces don't show involvement by that function, which makes it less likely that it matters, no? Greetings, Andres Freund
-
Re: logical decoding / rewrite map vs. maxAllocatedDescs
Tomas Vondra <tomas.vondra@2ndquadrant.com> — 2018-08-14T11:49:03Z
On 08/13/2018 04:49 PM, Andres Freund wrote: > Hi, > > On 2018-08-13 11:46:30 -0300, Alvaro Herrera wrote: >> On 2018-Aug-11, Tomas Vondra wrote: >> >>> Hmmm, it's difficult to compare "bt full" output, but my backtraces look >>> somewhat different (and all the backtraces I'm seeing are 100% exactly >>> the same). Attached for comparison. >> >> Hmm, looks similar enough to me -- at the bottom you have the executor >> doing its thing, then an AcceptInvalidationMessages in the middle >> section atop which sit a few more catalog accesses, and further up from >> that you have another AcceptInvalidationMessages with more catalog >> accesses. AFAICS that's pretty much the same thing Andres was >> describing. > > It's somewhat different because it doesn't seem to involve a reload of a > nailed table, which my traces did. I wasn't able to reproduce the crash > more than once, so I'm not at all sure how to properly verify the issue. > I'd appreciate if Thomas could try to do so again with the small patch I > provided. > I'll try in the evening. I've tried reproducing it on my laptop, but I can't make that happen for some reason - I know I've seen some crashes here, but all the reproducers were from the workstation I have at home. I wonder if there's some subtle difference between the two boxes, making it more likely on one of them ... the whole environment (distribution, packages, compiler, ...) should be exactly the same, though. The only thing I can think of is different CPU speed, possibly making some race conditions more/less likely. No idea. regards -- Tomas Vondra http://www.2ndQuadrant.com PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
-
Re: logical decoding / rewrite map vs. maxAllocatedDescs
Tomas Vondra <tomas.vondra@2ndquadrant.com> — 2018-08-14T14:05:29Z
On 08/14/2018 01:49 PM, Tomas Vondra wrote: > On 08/13/2018 04:49 PM, Andres Freund wrote: >> Hi, >> >> On 2018-08-13 11:46:30 -0300, Alvaro Herrera wrote: >>> On 2018-Aug-11, Tomas Vondra wrote: >>> >>>> Hmmm, it's difficult to compare "bt full" output, but my backtraces >>>> look >>>> somewhat different (and all the backtraces I'm seeing are 100% exactly >>>> the same). Attached for comparison. >>> >>> Hmm, looks similar enough to me -- at the bottom you have the executor >>> doing its thing, then an AcceptInvalidationMessages in the middle >>> section atop which sit a few more catalog accesses, and further up from >>> that you have another AcceptInvalidationMessages with more catalog >>> accesses. AFAICS that's pretty much the same thing Andres was >>> describing. >> >> It's somewhat different because it doesn't seem to involve a reload of a >> nailed table, which my traces did. I wasn't able to reproduce the crash >> more than once, so I'm not at all sure how to properly verify the issue. >> I'd appreciate if Thomas could try to do so again with the small patch I >> provided. >> > > I'll try in the evening. I've tried reproducing it on my laptop, but I > can't make that happen for some reason - I know I've seen some crashes > here, but all the reproducers were from the workstation I have at home. > > I wonder if there's some subtle difference between the two boxes, making > it more likely on one of them ... the whole environment (distribution, > packages, compiler, ...) should be exactly the same, though. The only > thing I can think of is different CPU speed, possibly making some race > conditions more/less likely. No idea. > I take that back - I can reproduce the crashes, both with and without the patch, all the way back to 9.6. Attached is a bunch of backtraces from various versions. There's a bit of variability depending on which pgbench script gets started first (insert.sql or vacuum.sql) - in one case (when vacuum is started before insert) the crash happens in InitPostgres/RelationCacheInitializePhase3, otherwise it happens in exec_simple_query. Another observation is that the failing COPY is not necessary, I can reproduce the crashes without this (so even with wal_level=replica). regards -- Tomas Vondra http://www.2ndQuadrant.com PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
-
Re: logical decoding / rewrite map vs. maxAllocatedDescs
Tomas Vondra <tomas.vondra@2ndquadrant.com> — 2018-08-14T21:26:30Z
On 8/14/18 10:05 AM, Tomas Vondra wrote: > ... > > I take that back - I can reproduce the crashes, both with and without > the patch, all the way back to 9.6. Attached is a bunch of backtraces > from various versions. There's a bit of variability depending on which > pgbench script gets started first (insert.sql or vacuum.sql) - in one > case (when vacuum is started before insert) the crash happens in > InitPostgres/RelationCacheInitializePhase3, otherwise it happens in > exec_simple_query. > > Another observation is that the failing COPY is not necessary, I can > reproduce the crashes without this (so even with wal_level=replica). > BTW I have managed to reproduce this on an old test server. If anyone wants to take a look, I can arrange ssh access to that machine (for trustworthy developers). Let me know. regards -- Tomas Vondra http://www.2ndQuadrant.com PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
-
Re: logical decoding / rewrite map vs. maxAllocatedDescs
Tomas Vondra <tomas.vondra@2ndquadrant.com> — 2018-08-16T15:07:17Z
On 08/11/2018 04:18 PM, Tomas Vondra wrote: > On 08/11/2018 04:15 PM, Tom Lane wrote: >> Tomas Vondra <tomas.vondra@2ndquadrant.com> writes: >>>>> On 08/09/2018 07:47 PM, Alvaro Herrera wrote: >>>>>> Actually, it seems to me that ApplyLogicalMappingFile is just leaking >>>>>> the file descriptor for no good reason. >> >>> I think the fix can be as simple as attached ... I'm mostly afk for the >>> weekend, so I'll commit & backpatch on Monday or so. >> >> LGTM. While you're at it, would you fix the misspelling three lines >> below this? >> >> * Check whether the TransactionOId 'xid' is in the pre-sorted array 'xip'. >> ^ > > Sure. > I've pushed this, and backpatched it all the way back to 9.4 where logical decoding was introduced. While this resolves the way to run out of file descriptors, I wonder if there are other trivial ways to trigger it (say, long-running transaction spanning many 'vacuum full pg_class' runs). Not sure, will try later. The other question is whether errors are handled correctly - as reported initially, I've seen this to trigger ERROR: XX000: subtransaction logged without previous top-level txn record I assume just fixing the error did not really fix that, so that if something else fails we might end up in the same state. regards -- Tomas Vondra http://www.2ndQuadrant.com PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services