Thread: BUG #16833: postgresql 13.1 process crash every hour

The following bug has been logged on the website:

Bug reference:      16833
Logged by:          Alex F
Email address:      phoedos16@gmail.com
PostgreSQL version: 13.1
Operating system:   4.14.209-160.339.amzn2.x86_64 #1 SMP Wed Dec 16 22
Description:

Postgresql run inside of  official docker container
https://hub.docker.com/_/postgres
psql (PostgreSQL) 13.1 (Debian 13.1-1.pgdg100+1)
on Amazon Linux 2 

Process crash inside docker containter 2-3 times per hour without any
additional information
./postgresql-Thu-00.log:2021-01-21 00:11:34 UTC [1]: user=,db=,app=,client=
LOG:  server process (PID 20071) was terminated by signal 11: Segmentation
fault
./postgresql-Thu-01.log:2021-01-21 01:11:50 UTC [1]: user=,db=,app=,client=
LOG:  server process (PID 23827) was terminated by signal 11: Segmentation
fault
./postgresql-Thu-02.log:2021-01-21 02:11:31 UTC [1]: user=,db=,app=,client=
LOG:  server process (PID 27974) was terminated by signal 11: Segmentation
fault
./postgresql-Thu-03.log:2021-01-21 03:11:56 UTC [1]: user=,db=,app=,client=
LOG:  server process (PID 31389) was terminated by signal 11: Segmentation
fault
./postgresql-Thu-04.log:2021-01-21 04:11:23 UTC [1]: user=,db=,app=,client=
LOG:  server process (PID 2544) was terminated by signal 11: Segmentation
fault
./postgresql-Thu-05.log:2021-01-21 05:11:52 UTC [1]: user=,db=,app=,client=
LOG:  server process (PID 5962) was terminated by signal 11: Segmentation
fault
./postgresql-Thu-06.log:2021-01-21 06:12:41 UTC [1]: user=,db=,app=,client=
LOG:  server process (PID 60) was terminated by signal 11: Segmentation
fault
./postgresql-Thu-07.log:2021-01-21 07:12:59 UTC [1]: user=,db=,app=,client=
LOG:  server process (PID 3810) was terminated by signal 11: Segmentation
fault
./postgresql-Thu-08.log:2021-01-21 08:12:37 UTC [1]: user=,db=,app=,client=
LOG:  server process (PID 7730) was terminated by signal 11: Segmentation
fault
./postgresql-Thu-09.log:2021-01-21 09:13:26 UTC [1]: user=,db=,app=,client=
LOG:  server process (PID 11257) was terminated by signal 11: Segmentation
fault
./postgresql-Thu-10.log:2021-01-21 10:13:05 UTC [1]: user=,db=,app=,client=
LOG:  server process (PID 14982) was terminated by signal 11: Segmentation
fault
./postgresql-Thu-11.log:2021-01-21 11:13:18 UTC [1]: user=,db=,app=,client=
LOG:  server process (PID 18503) was terminated by signal 11: Segmentation
fault
./postgresql-Thu-12.log:2021-01-21 12:13:04 UTC [1]: user=,db=,app=,client=
LOG:  server process (PID 22037) was terminated by signal 11: Segmentation
fault
./postgresql-Thu-13.log:2021-01-21 13:13:57 UTC [1]: user=,db=,app=,client=
LOG:  server process (PID 25484) was terminated by signal 11: Segmentation
fault
./postgresql-Thu-14.log:2021-01-21 14:13:15 UTC [1]: user=,db=,app=,client=
LOG:  server process (PID 29072) was terminated by signal 11: Segmentation
fault
./postgresql-Thu-15.log:2021-01-21 15:13:22 UTC [1]: user=,db=,app=,client=
LOG:  server process (PID 32657) was terminated by signal 11: Segmentation
fault
./postgresql-Thu-16.log:2021-01-21 16:13:15 UTC [1]: user=,db=,app=,client=
LOG:  server process (PID 3788) was terminated by signal 11: Segmentation
fault
./postgresql-Thu-17.log:2021-01-21 17:13:26 UTC [1]: user=,db=,app=,client=
LOG:  server process (PID 7306) was terminated by signal 11: Segmentation
fault
./postgresql-Thu-18.log:2021-01-21 18:12:58 UTC [1]: user=,db=,app=,client=
LOG:  server process (PID 11885) was terminated by signal 11: Segmentation
fault
./postgresql-Thu-19.log:2021-01-21 19:13:21 UTC [1]: user=,db=,app=,client=
LOG:  server process (PID 14442) was terminated by signal 11: Segmentation
fault
./postgresql-Thu-20.log:2021-01-21 20:13:36 UTC [1]: user=,db=,app=,client=
LOG:  server process (PID 17975) was terminated by signal 11: Segmentation
fault
./postgresql-Thu-21.log:2021-01-21 21:13:55 UTC [1]: user=,db=,app=,client=
LOG:  server process (PID 21631) was terminated by signal 11: Segmentation
fault
./postgresql-Thu-22.log:2021-01-21 22:14:45 UTC [1]: user=,db=,app=,client=
LOG:  server process (PID 25251) was terminated by signal 11: Segmentation
fault
./postgresql-Thu-23.log:2021-01-21 23:15:01 UTC [1]: user=,db=,app=,client=
LOG:  server process (PID 28851) was terminated by signal 11: Segmentation
fault

I can share postgresql.conf, process crash core dumps for analysis

PG Bug reporting form <noreply@postgresql.org> writes:
> Process crash inside docker containter 2-3 times per hour without any
> additional information
> ./postgresql-Thu-00.log:2021-01-21 00:11:34 UTC [1]: user=,db=,app=,client=
> LOG:  server process (PID 20071) was terminated by signal 11: Segmentation
> fault

Hm, please see if you can get a stack trace:

https://wiki.postgresql.org/wiki/Generating_a_stack_trace_of_a_PostgreSQL_backend

Also try to figure out what query(s) are causing the crash.
(It's unlikely that the postmaster log doesn't provide more
information than you've shared here.)

> I can share postgresql.conf, process crash core dumps for analysis

Core dumps are unlikely to help anyone else; they are too
machine-specific.  Not to mention that they might contain
sensitive data.  You'll need to examine them yourself.

            regards, tom lane

Hi,

On 2021-01-22 05:37:56 +0000, PG Bug reporting form wrote:
> Postgresql run inside of  official docker container
> https://hub.docker.com/_/postgres
> psql (PostgreSQL) 13.1 (Debian 13.1-1.pgdg100+1)
> on Amazon Linux 2 
> 
> Process crash inside docker containter 2-3 times per hour without any
> additional information

What kind of resource limits have you set up with docker?

Are there any kernel messages?

Greetings,

Andres Freund

Alex F <phoedos16@gmail.com> writes:
> Dear team, previously I wrote about postgresql crash (ref #16833)
> Unfortunately the issue is still present.

You still haven't provided a stack trace ... there is not much we
can do with the amount of information here.

            regards, tom lane

Alex F <phoedos16@gmail.com> writes:
> Think I was able to get a gdb stack trace. Logs attached.

> Program terminated with signal SIGSEGV, Segmentation fault.
> #0  0x00007ffa43a2c94d in __memmove_avx_unaligned_erms () from
> /lib64/libc.so.6
> (gdb) bt
> #0  0x00007ffa43a2c94d in __memmove_avx_unaligned_erms () from
> /lib64/libc.so.6
> #1  0x00000000004d67f5 in _bt_swap_posting ()
> #2  0x00000000004d792e in _bt_insertonpg ()
> #3  0x00000000004d9113 in _bt_doinsert ()
> #4  0x00000000004dc1a1 in btinsert ()
> #5  0x000000000060fa7f in ExecInsertIndexTuples ()
> #6  0x0000000000637078 in ExecInsert ()
> #7  0x00000000006379c7 in ExecModifyTable ()
> #8  0x00000000006107dc in standard_ExecutorRun ()
> #9  0x0000000000645695 in _SPI_execute_plan ()
> #10 0x0000000000645a3c in SPI_execute ()
> #11 0x00000000005c39ff in ExecRefreshMatView ()
> #12 0x000000000075799d in ProcessUtilitySlow.isra.4 ()
> #13 0x00000000007567ce in standard_ProcessUtility ()
> #14 0x0000000000754382 in PortalRunUtility ()
> #15 0x0000000000754d4d in PortalRunMulti ()
> #16 0x0000000000755763 in PortalRun ()
> #17 0x000000000075330b in PostgresMain ()
> #18 0x00000000006e2d8a in ServerLoop ()
> #19 0x00000000006e3df7 in PostmasterMain ()
> #20 0x00000000004883c2 in main ()

Hmm, looks like it's time to rope Peter Geoghegan in on this discussion.

            regards, tom lane

On Fri, May 14, 2021 at 7:57 AM Tom Lane <tgl@sss.pgh.pa.us> wrote:
> Hmm, looks like it's time to rope Peter Geoghegan in on this discussion.

I think that this is likely to be a fairly generic symptom of index
corruption. Ockham's razor does not seem to point to a software bug
because posting list splits are just not that complicated, and are
fairly common in the grand scheme of things. Docker is the kind of
thing that I wouldn't necessarily trust to not do something fishy with
LVM snapshotting -- I tend to suspect that that is a factor.

There was a very similar bug report and stack trace back in March.
That case was tied back to generic index corruption using amcheck,
with indexes corrupted that weren't implicated in the hard crash.

There is a real problem for me to fix here in any case:
_bt_swap_posting() is unnecessarily trusting of the state of the
posting list tuple (compared to _bt_split(), say). I still plan on
adding hardening to _bt_swap_posting() to avoid a hard crash.
Unfortunately I missed the opportunity to get that into 13.3, but I'll
get it into 13.4.

Alex should probably run amcheck to see what that throws up. It should
be possible to run amcheck on your database, which will detect corrupt
posting list tuples on Postgres 13. It's a contrib extension, so you
must first run "CREATE EXTENSION amcheck;". From there, you can run a
query like the following (you may want to customize this):

SELECT bt_index_parent_check(index => c.oid, heapallindexed => true),
c.relname,
c.relpages
FROM pg_index i
JOIN pg_opclass op ON i.indclass[0] = op.oid
JOIN pg_am am ON op.opcmethod = am.oid
JOIN pg_class c ON i.indexrelid = c.oid
JOIN pg_namespace n ON c.relnamespace = n.oid
WHERE am.amname = 'btree'
-- Don't check temp tables, which may be from another session:
AND c.relpersistence != 't'
-- Function may throw an error when this is omitted:
AND c.relkind = 'i' AND i.indisready AND i.indisvalid
ORDER BY c.relpages DESC;

If this query takes too long to complete you may find it useful to add
something to limit the indexes check, such as: AND n.nspname =
'public' -- that change to the SQL will make the query just test
indexes from the public schema.

Do "SET client_min_messages=DEBUG1 " to get a kind of rudimentary
progress indicator, if that seems useful to you.

The docs have further information on what this bt_index_parent_check
function does, should you need it:
https://www.postgresql.org/docs/13/amcheck.html

--
Peter Geoghegan

On Fri, May 14, 2021 at 12:12 PM Alex F <phoedos16@gmail.com> wrote:
> Dear Peter,
> Honestly don't know if you expect a response with amcheck results but anyway will paste it here:

It is helpful -- thanks!

It should be possible to avoid this problem by reindexing. Of course
it's important to eliminate whatever the source of the corruption is,
which might be much harder.

Could you execute exactly the same query, only this time use
"bt_index_check(index => c.oid, heapallindexed => true)" in place of
the bt_index_parent_check() call from the original query? Maybe there
is something more to be learned by just focussing on the leaf pages,
and not failing earlier on, in the parent pages. The less thorough
bt_index_check() function can sometimes show something interesting by
failing later than bt_index_parent_check() would fail with the same
index.

I note that the amcheck error message that you showed happens between
level 2 and level 1, neither of which are leaf level (that's level 0)
-- only leaf pages can have posting list tuples. To me this suggests
that the chances of corruption being a bug in deduplication
specifically are very remote (it's more likely to be a bug in some
other place, even). I'm always curious about real world corruption, so
I'd still appreciate seeing the bt_index_check() variant query's
output just to satisfy myself that that's what it is.

-- 
Peter Geoghegan

On Fri, May 14, 2021 at 1:13 PM Alex F <phoedos16@gmail.com> wrote:
> Thanks for your support!

I just pushed a commit that adds hardening that will be sufficient to
prevent this being a hard crash. Of course the index should not become
corrupt in the first place, but at least in Postgres 13.4 the same
scenario will result in an error rather than in a hard crash.

Thanks
-- 
Peter Geoghegan

On Mon, May 17, 2021 at 2:30 AM Alex F <phoedos16@gmail.com> wrote:
> Is it possible to extend the error log which can help to understand what exactly went wrong?
> For example, if error log look like this:
> 2021-05-14 06:10:54 UTC [22258]: user=,db=,app=,client= LOG:  server process (PID 22273) was terminated by signal 11:
Segmentationfault
 
> 2021-05-14 06:10:54 UTC [22258]: user=,db=,app=,client= DETAIL:  Failed process was running: REFRESH MATERIALIZED
VIEWCONCURRENTLY project.product_master_mv
 
>  ***CAUSED BY violated for index "name_original_idx_s"***
> e.g. trace marked with *** symbols can really help user to understand issue root cause and significantly decrease
databaserecovery time.
 
> In my case I had to create a separate VM, create a database from scratch and recover it from pg_dump. Unfortunately
mentionedactions took a significant downtime.
 

Once the database is corrupt it's more or less impossible to provide
hard guarantees about anything. We can only try our best to avoid the
worst consequences, such as a hard crash. This is guided by practical
experience and feedback from users. While this failure is clearly very
unfriendly, there is no getting around the fact that the real problem
began before there was any crash or error. Perhaps *long* before the
first crash, even.

> In case of master-standby configuration WAL replication does not save standby servers from broken objects (broken
indexin described case).
 
> Please advice is it possible to use logical replication here? From my understanding logical replication shouldn't
pushbroken objects on standby.
 

Unfortunately there are no simple answers. There is no reason to
believe that the corruption is limited to the indexes. I'd even say
that it's unlikely to be limited to indexes. What we see from amcheck
looks very much like storage level inconsistencies.

You'll need to do some kind of root cause analysis, so that you can
find the underlying issue and systematically eliminate it.

-- 
Peter Geoghegan