Обсуждение: Please help me debug regular segfaults on 8.3.10

Hi,

one of our pgsql instances recently started to segfault multiple times a
week. I tried a couple of things to pin it down to a certain query
or job but failed to find any pattern. All I can offer is some notes
and a set of similar looking back traces.

Thanks in advance.



Machine details
---------------
* CentOS release 5.4 (Final)
* Linux 2.6.18-164.15.1.el5 #1 SMP Wed Mar 17 11:30:06 EDT 2010 x86_64
x86_64 x86_64 GNU/Linux
* 4x Quad-Core AMD Opteron 8354
* 64GB RAM (ECC)



PostgreSQL packages
-------------------
* postgresql-8.3.10-2PGDG.el5
* postgresql-contrib-8.3.10-2PGDG.el5
* postgresql-devel-8.3.10-2PGDG.el5
* postgresql-libs-8.3.10-2PGDG.el5
* postgresql-plperl-8.3.10-2PGDG.el5
* postgresql-plpython-8.3.10-2PGDG.el5
* postgresql-pltcl-8.3.10-2PGDG.el5
* postgresql-server-8.3.10-2PGDG.el5



Environment
-----------
* Multiple databases with a total of 1TB in size
* So far the back traces show three different databases
* Some larger hash indexes exist (requiring reindex after each crash)
* The only loaded PL is pl/pgsql
* The system is doing around 3000 TPS constantly



Things that didn't make any change
----------------------------------
* Updated from 8.3.7 to 8.3.10
* Updated OS kernel



2010-05-04 | core.21207
-----------------------
Core was generated by `postgres: <user> <database_1> <client ip>('.
Program terminated with signal 11, Segmentation fault.
[New process 21207]
#0  0x000000000066acae in pfree ()
(gdb) bt
#0  0x000000000066acae in pfree ()
#1  0x0000000000648c6e in ?? ()
#2  0x0000000000648f34 in ?? ()
#3  0x00000000006493d4 in RelationCacheInvalidateEntry ()
#4  0x0000000000644fcd in ?? ()
#5  0x0000000000644882 in ?? ()
#6  0x00000000006448be in CommandEndInvalidationMessages ()
#7  0x0000000000472993 in CommandCounterIncrement ()
#8  0x00000000005342ea in ?? ()
#9  0x0000000000534543 in SPI_execute_plan ()
#10 0x00002ad2863f0148 in ?? () from /usr/lib64/pgsql/plpgsql.so
#11 0x00002ad2863f1a26 in ?? () from /usr/lib64/pgsql/plpgsql.so
#12 0x00002ad2863f3372 in ?? () from /usr/lib64/pgsql/plpgsql.so
#13 0x00002ad2863f3ce5 in plpgsql_exec_function () from
/usr/lib64/pgsql/plpgsql.so
#14 0x00002ad2863ea7be in plpgsql_call_handler () from
/usr/lib64/pgsql/plpgsql.so
#15 0x000000000052023e in ExecMakeFunctionResult ()
#16 0x000000000051d1f3 in ExecProject ()
#17 0x000000000052df13 in ExecResult ()
#18 0x000000000051cc66 in ExecProcNode ()
#19 0x000000000051bedf in ExecutorRun ()
#20 0x00000000005b1481 in ?? ()
#21 0x00000000005b2689 in PortalRun ()
#22 0x00000000005ae3b0 in ?? ()
#23 0x00000000005af038 in PostgresMain ()
#24 0x00000000005856a7 in ?? ()
#25 0x000000000058632b in PostmasterMain ()
#26 0x000000000053eece in main ()


2010-04-29 | core.20832
-----------------------
Core was generated by `postgres: <user> <database_1> <client ip>('.
Program terminated with signal 11, Segmentation fault.
[New process 20832]
#0  0x000000000066acae in pfree ()
(gdb) bt
#0  0x000000000066acae in pfree ()
#1  0x0000000000648c6e in ?? ()
#2  0x0000000000648f34 in ?? ()
#3  0x00000000006493d4 in RelationCacheInvalidateEntry ()
#4  0x0000000000644fcd in ?? ()
#5  0x0000000000644882 in ?? ()
#6  0x00000000006448be in CommandEndInvalidationMessages ()
#7  0x0000000000472993 in CommandCounterIncrement ()
#8  0x00000000005342ea in ?? ()
#9  0x0000000000534543 in SPI_execute_plan ()
#10 0x00002b41879e1148 in ?? () from /usr/lib64/pgsql/plpgsql.so
#11 0x00002b41879e2a26 in ?? () from /usr/lib64/pgsql/plpgsql.so
#12 0x00002b41879e4372 in ?? () from /usr/lib64/pgsql/plpgsql.so
#13 0x00002b41879e4ce5 in plpgsql_exec_function () from
/usr/lib64/pgsql/plpgsql.so
#14 0x00002b41879db7be in plpgsql_call_handler () from
/usr/lib64/pgsql/plpgsql.so
#15 0x000000000052023e in ExecMakeFunctionResult ()
#16 0x000000000051d1f3 in ExecProject ()
#17 0x000000000052df13 in ExecResult ()
#18 0x000000000051cc66 in ExecProcNode ()
#19 0x000000000051bedf in ExecutorRun ()
#20 0x00000000005b1481 in ?? ()
#21 0x00000000005b2689 in PortalRun ()
#22 0x00000000005ae3b0 in ?? ()
#23 0x00000000005af038 in PostgresMain ()
#24 0x00000000005856a7 in ?? ()
#25 0x000000000058632b in PostmasterMain ()
#26 0x000000000053eece in main ()


2010-04-27 | core.25421
-----------------------
Core was generated by `postgres: <user> <database_1> <client ip>('.
Program terminated with signal 11, Segmentation fault.
[New process 25421]
#0  0x000000000066acae in pfree ()
(gdb) bt
#0  0x000000000066acae in pfree ()
#1  0x0000000000648c6e in ?? ()
#2  0x0000000000648f34 in ?? ()
#3  0x00000000006493d4 in RelationCacheInvalidateEntry ()
#4  0x0000000000644fcd in ?? ()
#5  0x0000000000644882 in ?? ()
#6  0x00000000006448be in CommandEndInvalidationMessages ()
#7  0x0000000000472993 in CommandCounterIncrement ()
#8  0x00000000005342ea in ?? ()
#9  0x0000000000534543 in SPI_execute_plan ()
#10 0x00002b41879e1148 in ?? () from /usr/lib64/pgsql/plpgsql.so
#11 0x00002b41879e2a26 in ?? () from /usr/lib64/pgsql/plpgsql.so
#12 0x00002b41879e4372 in ?? () from /usr/lib64/pgsql/plpgsql.so
#13 0x00002b41879e4ce5 in plpgsql_exec_function () from
/usr/lib64/pgsql/plpgsql.so
#14 0x00002b41879db7be in plpgsql_call_handler () from
/usr/lib64/pgsql/plpgsql.so
#15 0x000000000052023e in ExecMakeFunctionResult ()
#16 0x000000000051d1f3 in ExecProject ()
#17 0x000000000052df13 in ExecResult ()
#18 0x000000000051cc66 in ExecProcNode ()
#19 0x000000000051bedf in ExecutorRun ()
#20 0x00000000005b1481 in ?? ()
#21 0x00000000005b2689 in PortalRun ()
#22 0x00000000005ae3b0 in ?? ()
#23 0x00000000005af038 in PostgresMain ()
#24 0x00000000005856a7 in ?? ()
#25 0x000000000058632b in PostmasterMain ()
#26 0x000000000053eece in main ()


2010-04-24 | core.23631
-----------------------
Core was generated by `postgres: <user> <database_2> <client ip>('.
Program terminated with signal 11, Segmentation fault.
[New process 23631]
#0  0x000000000066acae in pfree ()
(gdb) bt
#0  0x000000000066acae in pfree ()
#1  0x0000000000648c6e in ?? ()
#2  0x0000000000648f34 in ?? ()
#3  0x00000000006493d4 in RelationCacheInvalidateEntry ()
#4  0x0000000000644fcd in ?? ()
#5  0x0000000000644882 in ?? ()
#6  0x00000000006448be in CommandEndInvalidationMessages ()
#7  0x0000000000472993 in CommandCounterIncrement ()
#8  0x00000000005342ea in ?? ()
#9  0x0000000000534543 in SPI_execute_plan ()
#10 0x00002b41879a0148 in ?? () from /usr/lib64/pgsql/plpgsql.so
#11 0x00002b41879a1a26 in ?? () from /usr/lib64/pgsql/plpgsql.so
#12 0x00002b41879a3372 in ?? () from /usr/lib64/pgsql/plpgsql.so
#13 0x00002b41879a3ce5 in plpgsql_exec_function () from
/usr/lib64/pgsql/plpgsql.so
#14 0x00002b418799a7be in plpgsql_call_handler () from
/usr/lib64/pgsql/plpgsql.so
#15 0x000000000052023e in ExecMakeFunctionResult ()
#16 0x000000000051d1f3 in ExecProject ()
#17 0x000000000052df13 in ExecResult ()
#18 0x000000000051cc66 in ExecProcNode ()
#19 0x000000000051bedf in ExecutorRun ()
#20 0x00000000005b1481 in ?? ()
#21 0x00000000005b2689 in PortalRun ()
#22 0x00000000005ae3b0 in ?? ()
#23 0x00000000005af038 in PostgresMain ()
#24 0x00000000005856a7 in ?? ()
#25 0x000000000058632b in PostmasterMain ()
#26 0x000000000053eece in main ()


2010-04-23 | core.9419
-----------------------
Core was generated by `postgres: <user> <database_1> <client ip>('.
Program terminated with signal 11, Segmentation fault.
[New process 9419]
#0  0x000000000066acae in pfree ()
(gdb) bt
#0  0x000000000066acae in pfree ()
#1  0x0000000000648c6e in ?? ()
#2  0x0000000000648f34 in ?? ()
#3  0x00000000006493d4 in RelationCacheInvalidateEntry ()
#4  0x0000000000644fcd in ?? ()
#5  0x0000000000644882 in ?? ()
#6  0x00000000006448be in CommandEndInvalidationMessages ()
#7  0x0000000000472993 in CommandCounterIncrement ()
#8  0x00000000005342ea in ?? ()
#9  0x0000000000534543 in SPI_execute_plan ()
#10 0x00002b3acaef4148 in ?? () from /usr/lib64/pgsql/plpgsql.so
#11 0x00002b3acaef5a26 in ?? () from /usr/lib64/pgsql/plpgsql.so
#12 0x00002b3acaef7372 in ?? () from /usr/lib64/pgsql/plpgsql.so
#13 0x00002b3acaef7ce5 in plpgsql_exec_function () from
/usr/lib64/pgsql/plpgsql.so
#14 0x00002b3acaeee7be in plpgsql_call_handler () from
/usr/lib64/pgsql/plpgsql.so
#15 0x000000000052023e in ExecMakeFunctionResult ()
#16 0x000000000051d1f3 in ExecProject ()
#17 0x000000000052df13 in ExecResult ()
#18 0x000000000051cc66 in ExecProcNode ()
#19 0x000000000051bedf in ExecutorRun ()
#20 0x00000000005b1481 in ?? ()
#21 0x00000000005b2689 in PortalRun ()
#22 0x00000000005ae3b0 in ?? ()
#23 0x00000000005af038 in PostgresMain ()
#24 0x00000000005856a7 in ?? ()
#25 0x000000000058632b in PostmasterMain ()
#26 0x000000000053eece in main ()


2010-04-22 | core.16801
-----------------------
Core was generated by `postgres: <user> <database_2> <client ip>('.
Program terminated with signal 11, Segmentation fault.
[New process 16801]
#0  0x000000000066acae in pfree ()
(gdb) bt
#0  0x000000000066acae in pfree ()
#1  0x0000000000648c6e in ?? ()
#2  0x0000000000648f34 in ?? ()
#3  0x00000000006493d4 in RelationCacheInvalidateEntry ()
#4  0x0000000000644fcd in ?? ()
#5  0x0000000000644882 in ?? ()
#6  0x00000000006448be in CommandEndInvalidationMessages ()
#7  0x0000000000472993 in CommandCounterIncrement ()
#8  0x00000000005342ea in ?? ()
#9  0x0000000000534543 in SPI_execute_plan ()
#10 0x00002b3acaeb3148 in ?? () from /usr/lib64/pgsql/plpgsql.so
#11 0x00002b3acaeb4a26 in ?? () from /usr/lib64/pgsql/plpgsql.so
#12 0x00002b3acaeb6372 in ?? () from /usr/lib64/pgsql/plpgsql.so
#13 0x00002b3acaeb6ce5 in plpgsql_exec_function () from
/usr/lib64/pgsql/plpgsql.so
#14 0x00002b3acaead7be in plpgsql_call_handler () from
/usr/lib64/pgsql/plpgsql.so
#15 0x000000000052023e in ExecMakeFunctionResult ()
#16 0x000000000051d1f3 in ExecProject ()
#17 0x000000000052df13 in ExecResult ()
#18 0x000000000051cc66 in ExecProcNode ()
#19 0x000000000051bedf in ExecutorRun ()
#20 0x00000000005b1481 in ?? ()
#21 0x00000000005b2689 in PortalRun ()
#22 0x00000000005ae3b0 in ?? ()
#23 0x00000000005af038 in PostgresMain ()
#24 0x00000000005856a7 in ?? ()
#25 0x000000000058632b in PostmasterMain ()
#26 0x000000000053eece in main ()


2010-04-15 | core.32242
-----------------------
Core was generated by `postgres: <user> <database_3> <client ip>('.
Program terminated with signal 11, Segmentation fault.
[New process 32242]
#0  0x000000000066acae in pfree ()
(gdb) bt
#0  0x000000000066acae in pfree ()
#1  0x0000000000648c6e in ?? ()
#2  0x0000000000648f34 in ?? ()
#3  0x00000000006493d4 in RelationCacheInvalidateEntry ()
#4  0x0000000000644fcd in ?? ()
#5  0x0000000000644882 in ?? ()
#6  0x00000000006448be in CommandEndInvalidationMessages ()
#7  0x0000000000472993 in CommandCounterIncrement ()
#8  0x0000000000525c25 in fmgr_sql ()
#9  0x000000000052023e in ExecMakeFunctionResult ()
#10 0x000000000051d1f3 in ExecProject ()
#11 0x000000000052df13 in ExecResult ()
#12 0x000000000051cc66 in ExecProcNode ()
#13 0x000000000051bedf in ExecutorRun ()
#14 0x00000000005b1481 in ?? ()
#15 0x00000000005b2689 in PortalRun ()
#16 0x00000000005ae3b0 in ?? ()
#17 0x00000000005af038 in PostgresMain ()
#18 0x00000000005856a7 in ?? ()
#19 0x000000000058632b in PostmasterMain ()
#20 0x000000000053eece in main ()


2010-04-14 | core.10776
-----------------------
Core was generated by `postgres: <user> <database_1> <client ip>('.
Program terminated with signal 11, Segmentation fault.
[New process 10776]
#0  0x000000000066acae in pfree ()
(gdb) bt
#0  0x000000000066acae in pfree ()
#1  0x0000000000648c6e in ?? ()
#2  0x0000000000648f34 in ?? ()
#3  0x00000000006493d4 in RelationCacheInvalidateEntry ()
#4  0x0000000000644fcd in ?? ()
#5  0x0000000000644882 in ?? ()
#6  0x00000000006448be in CommandEndInvalidationMessages ()
#7  0x0000000000472993 in CommandCounterIncrement ()
#8  0x00000000005342ea in ?? ()
#9  0x0000000000534543 in SPI_execute_plan ()
#10 0x00002b3acaeb3148 in ?? () from /usr/lib64/pgsql/plpgsql.so
#11 0x00002b3acaeb4a26 in ?? () from /usr/lib64/pgsql/plpgsql.so
#12 0x00002b3acaeb6372 in ?? () from /usr/lib64/pgsql/plpgsql.so
#13 0x00002b3acaeb6ce5 in plpgsql_exec_function () from
/usr/lib64/pgsql/plpgsql.so
#14 0x00002b3acaead7be in plpgsql_call_handler () from
/usr/lib64/pgsql/plpgsql.so
#15 0x000000000052023e in ExecMakeFunctionResult ()
#16 0x000000000051d1f3 in ExecProject ()
#17 0x000000000052df13 in ExecResult ()
#18 0x000000000051cc66 in ExecProcNode ()
#19 0x000000000051bedf in ExecutorRun ()
#20 0x00000000005b1481 in ?? ()
#21 0x00000000005b2689 in PortalRun ()
#22 0x00000000005ae3b0 in ?? ()
#23 0x00000000005af038 in PostgresMain ()
#24 0x00000000005856a7 in ?? ()
#25 0x000000000058632b in PostmasterMain ()
#26 0x000000000053eece in main ()

pgsql wrote:
> Hi,
>
> one of our pgsql instances recently started to segfault multiple times a
> week. I tried a couple of things to pin it down to a certain query
> or job but failed to find any pattern. All I can offer is some notes
> and a set of similar looking back traces.

Please install the debuginfo package(s).  Have you got some external
module installed?

--
Alvaro Herrera                                http://www.CommandPrompt.com/
PostgreSQL Replication, Consulting, Custom Development, 24x7 support

pgsql <pgsql@lavabit.com> writes:
> one of our pgsql instances recently started to segfault multiple times a
> week. I tried a couple of things to pin it down to a certain query
> or job but failed to find any pattern. All I can offer is some notes
> and a set of similar looking back traces.

All of those traces seem to be within plpgsql functions that are doing
some sort of schema update on a table.  Sure you can't pin it down a
little better?  Looking at debug_query_string in the core dumps would
at least show what SQL command is calling the function(s) --- and I
wouldn't be surprised if there's exactly one function involved here.

As per Alvaro's suggestion, installing postgresql-debuginfo would
make the stack traces a lot more useful, too.

            regards, tom lane

pgsql <pgsql@lavabit.com> writes:
> one of our pgsql instances recently started to segfault multiple times a
> week. I tried a couple of things to pin it down to a certain query
> or job but failed to find any pattern. All I can offer is some notes
> and a set of similar looking back traces.

BTW, there is a post-8.3.10 patch for a problem that could easily match
what you are showing.  Dunno if you are up for applying patches
yourself, but if so try adding this one:
http://archives.postgresql.org/pgsql-committers/2010-04/msg00122.php

Now, the fact that that's fixing a problem introduced in January might
mean it's not what you're seeing.  However, the January patch was fixing
a different issue in the same general area.  It could be that your app
was managing to tickle both the old bug (in 8.3.7) and the new one (in
8.3.10).

            regards, tom lane

On 5/05/2010 5:27 AM, Alvaro Herrera wrote:
> pgsql wrote:
>> Hi,
>>
>> one of our pgsql instances recently started to segfault multiple times a
>> week. I tried a couple of things to pin it down to a certain query
>> or job but failed to find any pattern. All I can offer is some notes
>> and a set of similar looking back traces.
>
> Please install the debuginfo package(s).

See:


http://wiki.postgresql.org/wiki/Getting_a_stack_trace_of_a_running_PostgreSQL_backend_on_Linux/BSD#Installing_External_symbols


--
Craig Ringer

Alvaro Herrera wrote:
> pgsql wrote:
>> Hi,
>>
>> one of our pgsql instances recently started to segfault multiple times a
>> week. I tried a couple of things to pin it down to a certain query
>> or job but failed to find any pattern. All I can offer is some notes
>> and a set of similar looking back traces.
>
> Please install the debuginfo package(s).  Have you got some external
> module installed?

..for whatever reason I cannot get the postmaster provided by
postgresql-debuginfo-8.3.10-2PGDG.el5.x86_64.rpm to run; it immediately
causes a segfault:

ld-linux-x86-64[4286] general protection rip:3b2ca06471 rsp:7fff9a5077c0
error:0

However I just build 8.3.10 from source with debug enabled. As soon as
it crashes I'll post the new back trace.

Thanks!

Tom Lane wrote:
> pgsql <pgsql@lavabit.com> writes:
> Looking at debug_query_string in the core dumps would
> at least show what SQL command is calling the function(s) --- and I
> wouldn't be surprised if there's exactly one function involved here.

Content of debug_query_string:

core.21207
$1 = 63106368

core.20832
$1 = 292449712

core.25421
$1 = 292450320

core.23631
$1 = 292450000

core.9419
$1 = 284979152

core.16801
$1 = 284978992

core.32242
$1 = 284971248

core.10776
$1 = 284978832


> As per Alvaro's suggestion, installing postgresql-debuginfo would
> make the stack traces a lot more useful, too.

Build from source (without the relcache patch) with debug enabled;
waiting for the next crash.


Thank you

pgsql <pgsql@lavabit.com> writes:
> Tom Lane wrote:
>> Looking at debug_query_string in the core dumps would
>> at least show what SQL command is calling the function(s) --- and I
>> wouldn't be surprised if there's exactly one function involved here.

> Content of debug_query_string:

> core.21207
> $1 = 63106368

Um, that's not too helpful, we want to see the string it's pointing at.
In a non-debug build you probably need to say
    p (char *) debug_query_string
or something like that.

            regards, tom lane

Tom Lane wrote:
> pgsql <pgsql@lavabit.com> writes:
>> Tom Lane wrote:
>>> Looking at debug_query_string in the core dumps would
>>> at least show what SQL command is calling the function(s) --- and I
>>> wouldn't be surprised if there's exactly one function involved here.
>
>> Content of debug_query_string:
>
>> core.21207
>> $1 = 63106368
>
> Um, that's not too helpful, we want to see the string it's pointing at.

Sorry about that. All statements are calling one of two pl/pgsql
functions. While that information already helps me a lot, it'll take me
a while to step through the code. Those functions are outer wrappers
calling many other procedures.

Thank you very much.

pgsql <pgsql@lavabit.com> writes:
> Tom Lane wrote:
>> Um, that's not too helpful, we want to see the string it's pointing at.

> Sorry about that. All statements are calling one of two pl/pgsql
> functions. While that information already helps me a lot, it'll take me
> a while to step through the code. Those functions are outer wrappers
> calling many other procedures.

Well, the stack trace you showed previously indicates that the crash is
happening in the outermost plpgsql function (ie, one called directly
from a client SQL command).  However it's certainly true that the crash
might be a consequence of something that had been done a bit earlier in
another function called by this one.

Keep in mind that the crash very likely doesn't happen when you simply
step through the function in isolation.  If it is the same as or
related to the previously-fixed bug, it would only happen if a cache
flush event happened at just the wrong time (as a consequence of
sufficiently many concurrent catalog updates issued by other processes).

            regards, tom lane

Tom Lane wrote:
> pgsql <pgsql@lavabit.com> writes:
>> Tom Lane wrote:
>>> Um, that's not too helpful, we want to see the string it's pointing at.
>
>> Sorry about that. All statements are calling one of two pl/pgsql
>> functions. While that information already helps me a lot, it'll take me
>> a while to step through the code. Those functions are outer wrappers
>> calling many other procedures.
>
> Well, the stack trace you showed previously indicates that the crash is
> happening in the outermost plpgsql function (ie, one called directly
> from a client SQL command).  However it's certainly true that the crash
> might be a consequence of something that had been done a bit earlier in
> another function called by this one.

Sorry for the late reply. The only DDL performed is indeed in the outer
function and it's a TRUNCATE, immediately followed by an INSERT SELECT
to repopulate the truncated table.

As mentioned, I build 8.3.10 from source using --enable-debug
--enable-cassert. I had issues with this version causing protection
faults. Also the backtrace I got from that still doesn't include line
numbers and arguments. So I assume I missed something important when
doing the build?

postgres[7172] general protection rip:44abd8 rsp:7fff9195a060 error:0

Core was generated by `postgres: <user> <database> <client_ip>(51'.
Program terminated with signal 11, Segmentation fault.
[New process 7172]
#0  0x000000000044abd8 in index_form_tuple ()
(gdb) bt
#0  0x000000000044abd8 in index_form_tuple ()
#1  0x0000000000000001 in ?? ()
#2  0x000000000153d968 in ?? ()
#3  0x0000000000670634 in tuplesort_performsort ()
#4  0x0000000000000000 in ?? ()

I decided to strip the debug options (as they somehow seem to cause
issue on that system) and instead apply the patch you pointed out. No
crashes since then anymore.

Thanks for your support.