Thread: Autovacuum daemon terminated by signal 11
Hello, I have a server running PostgreSQL 8.1.15-0etch1 (Debian etch) that was recently put into production. Last week a developer started having a problem with his psql connection being terminated every couple of minutes when he was running a query. When I look through the logs, I noticed this message. 2009-01-09 08:09:46 CST LOG: autovacuum process (PID 15012) was terminated by signal 11 I looked through the logs some more and I noticed that this was occurring every minute or so. The database is a pretty heavily utilized system (judging by the age(datfrozenxid) from pg_database, the system had run approximately 500 million queries in less than a week). I noticed that right before every autovacuum termination, it tried to autovacuum a database. 2009-01-09 08:09:46 CST LOG: transaction ID wrap limit is 4563352, limited by database "database_name" It was always showing the same database, so I decided to manually vacuum the database. Once that was done (it was successful the first time without errors), the problem seemed to go away. I went ahead and manually vacuumed the remaining databases just to take care of the potential xid wraparound issue. I figured it was just an isolated incident, until it started happening again this week. Same scenario as before: over 500 million queries since the beginning of this week and autovacuum dying on the same database every time. However, the problematic database was different than last time, so it doesn't seem to be specific to one particular database. Looking through the archives I've seen this (exact?) same problem crop up before, but it was addressed in Postgres 8.1.1 http://archives.postgresql.org/pgsql-bugs/2006-01/msg00014.php This article also mentioned the previous bug was related to triggers on the table, but the second time this happened to me, the database in question only has two simple tables (no triggers, one foreign key linking them, a few btree indices). What else can I do to determine the cause of this? For the time being, I should be able to setup a cron job to run a manual vacuum every other day to ensure that age(datfrozenxid) stays low, but I'd like to understand what would be causing this. Justin Pasher
hi, all:
there is a function in postgresql contrib "int_arrgreagte":
CREATE OR REPLACE FUNCTION int_array_enum(int4[])
RETURNS setof integer
AS '$libdir/int_aggregate','int_enum'
LANGUAGE C IMMUTABLE STRICT;
I can use this function like this:
chry=# SELECT int_array_enum('{1,2}');
or
chry=# SELECT * from int_array_enum('{1,2}');
result:
int_array_enum
----------------
1
2
also, I can use it like this:
SELECT int_array_enum('{1,2}'), int_array_enum('{1,3}');
result:
int_array_enum | int_array_enum
----------------+----------------
1 | 1
2 | 3
I try to write my own function with the same return type in plpgsql:
create or replace function my_int_array_enum(state integer[]) returns
setof integer as $$
declare
i integer;
begin
for i in array_lower(state,1)..array_upper(state,1) loop
return next state[i];
end loop;
return;
end;
$$ language 'plpgsql' immutable;
but, when I use my function like this: test=# SELECT
my_int_array_enum('{1,2}');
I got the error said as below:
ERROR: set-valued function called in context that cannot accept a set
(I know, SELECT * from my_int_array_enum('{1,2}') is ok)
can anybody tell me the reason, thanks for any help:D
regards,
Justin Pasher wrote: > Hello, > > I have a server running PostgreSQL 8.1.15-0etch1 (Debian etch) that was > recently put into production. Last week a developer started having a problem > with his psql connection being terminated every couple of minutes when he > was running a query. When I look through the logs, I noticed this message. > > 2009-01-09 08:09:46 CST LOG: autovacuum process (PID 15012) was terminated > by signal 11 Segmentation fault - probably a bug or bad RAM. > I looked through the logs some more and I noticed that this was occurring > every minute or so. The database is a pretty heavily utilized system > (judging by the age(datfrozenxid) from pg_database, the system had run > approximately 500 million queries in less than a week). I noticed that right > before every autovacuum termination, it tried to autovacuum a database. > > 2009-01-09 08:09:46 CST LOG: transaction ID wrap limit is 4563352, limited > by database "database_name" > > It was always showing the same database, so I decided to manually vacuum the > database. Once that was done (it was successful the first time without > errors), the problem seemed to go away. I went ahead and manually vacuumed > the remaining databases just to take care of the potential xid wraparound > issue. I'd be suspicious of possible corruption in autovacuum's internal data. Can you trace these problems back to a power-outage or system crash? It doesn't look like "database_name" itself since you vacuumed that successfully. If autovacuum is running normally now, that might indicate it was something in the way autovacuum was keeping track of "database_name". It's also probably worth running some memory tests on the server - (memtest86 or similar) to see if that shows anything. Was it *always* the autovacuum process getting sig11? If not then it might just be a pattern of usage that makes it more likely to use some bad RAM. -- Richard Huxton Archonet Ltd
Richard Huxton wrote: > Justin Pasher wrote: > >> Hello, >> >> I have a server running PostgreSQL 8.1.15-0etch1 (Debian etch) that was >> recently put into production. Last week a developer started having a problem >> with his psql connection being terminated every couple of minutes when he >> was running a query. When I look through the logs, I noticed this message. >> >> 2009-01-09 08:09:46 CST LOG: autovacuum process (PID 15012) was terminated >> by signal 11 >> > > Segmentation fault - probably a bug or bad RAM. > It's a relatively new machine, but that's obviously a possibility with any hardware. I haven't seen any other programs experiencing problems on the box, but the Postgres daemon is the one that is primarily utilized, so it's a little biased toward that. >> I looked through the logs some more and I noticed that this was occurring >> every minute or so. The database is a pretty heavily utilized system >> (judging by the age(datfrozenxid) from pg_database, the system had run >> approximately 500 million queries in less than a week). I noticed that right >> before every autovacuum termination, it tried to autovacuum a database. >> >> 2009-01-09 08:09:46 CST LOG: transaction ID wrap limit is 4563352, limited >> by database "database_name" >> >> It was always showing the same database, so I decided to manually vacuum the >> database. Once that was done (it was successful the first time without >> errors), the problem seemed to go away. I went ahead and manually vacuumed >> the remaining databases just to take care of the potential xid wraparound >> issue. >> > > I'd be suspicious of possible corruption in autovacuum's internal data. > Can you trace these problems back to a power-outage or system crash? It > doesn't look like "database_name" itself since you vacuumed that > successfully. If autovacuum is running normally now, that might indicate > it was something in the way autovacuum was keeping track of "database_name". > The server hasn't been rebooted since it was installed (about 9 months ago, but only being utilized within the past month), so there haven't been any crashes or power outages. The only abnormal things I can find in the Postgres logs are the autovacuum segfaults. Looking in the logs today, it looks like it's still happening (once again on a different database). I manually vacuumed that one database and the problem went away (for now). Are there any internal Postgres tables I can look at that may shed some light on this? Any particular maintenance commands that could be run for repair? > It's also probably worth running some memory tests on the server - > (memtest86 or similar) to see if that shows anything. Was it *always* > the autovacuum process getting sig11? If not then it might just be a > pattern of usage that makes it more likely to use some bad RAM I might try the memtest if we can actually get the databases off of the server to allow some downtime. None of the logs indicate anything else acting abnormally or being terminated abnormally, just the autovacuum daemon. From what I can tell, the segfaults only when the databases pass the half way point (when age(datfrozenxid) exceeds around 1500000000). When this is not the case, the segfaults do not occur according to the logs. Justin Pasher
>> Justin Pasher wrote: > Are there any internal Postgres tables I can look at that may shed some > light on this? Any particular maintenance commands that could be run for > repair? Please obtain a backtrace from the core file. If there's no core file, please set "ulimit -c unlimited" in the Postgres start script and restart it so that it is allowed to produce one. -- Alvaro Herrera http://www.CommandPrompt.com/ The PostgreSQL Company - Command Prompt, Inc.
Justin Pasher <justinp@newmediagateway.com> writes:
> Richard Huxton wrote:
>> Segmentation fault - probably a bug or bad RAM.
> It's a relatively new machine, but that's obviously a possibility with
> any hardware. I haven't seen any other programs experiencing problems on
> the box, but the Postgres daemon is the one that is primarily utilized,
> so it's a little biased toward that.
I agree that the behavior seems a bit too specific to be a hardware
issue.
Can you get a stack trace from the crash? You might need to restart the
postmaster under "ulimit -c unlimited" to get a core dump from the
crashing autovacuum process.
regards, tom lane
Tom Lane wrote: > Justin Pasher <justinp@newmediagateway.com> writes: > >> Richard Huxton wrote: >> >>> Segmentation fault - probably a bug or bad RAM. >>> >> It's a relatively new machine, but that's obviously a possibility with >> any hardware. I haven't seen any other programs experiencing problems on >> the box, but the Postgres daemon is the one that is primarily utilized, >> so it's a little biased toward that. >> > > I agree that the behavior seems a bit too specific to be a hardware > issue. > > Can you get a stack trace from the crash? You might need to restart the > postmaster under "ulimit -c unlimited" to get a core dump from the > crashing autovacuum process. > > regards, tom lane > I'm working on getting the database running on another server so I can perform more tests. So far I was able to get a copy of the cluster up and running. Once the autovacuum process kicked in, it started experiencing the same segfault on the new box. At this point, the hardware on the original box no longer seems to be a culprit (assuming the data files themselves aren't corrupted and I didn't just bring the corruption along with the cluster). I'll let you know when I get a chance to get a core dump from the process. I assume I will need a version of Postgres built with debug symbols for it to be useful? I'm not seeing one in the standard Debian repositories, so I might have to compile from source. Justin Pasher
Justin Pasher <justinp@newmediagateway.com> writes:
> I'll let you know when I get a chance to get a core dump from the
> process. I assume I will need a version of Postgres built with debug
> symbols for it to be useful? I'm not seeing one in the standard Debian
> repositories, so I might have to compile from source.
Having debug symbols would be more useful, but unless the binary is
totally stripped, a backtrace might provide enough info without that.
Try it and see if you get any function names in the trace, or only
numbers.
(BTW, does Debian have anything comparable to Red Hat's debuginfo
packages? You might be able to get the debug symbols without having
to recompile for yourself. Recompile is a bit of a pain since you have
to take care to match the original compilation options exactly.)
regards, tom lane
Tom Lane wrote: > Having debug symbols would be more useful, but unless the binary is > totally stripped, a backtrace might provide enough info without that. > Try it and see if you get any function names in the trace, or only > numbers. > > (BTW, does Debian have anything comparable to Red Hat's debuginfo > packages? You might be able to get the debug symbols without having > to recompile for yourself. Recompile is a bit of a pain since you have > to take care to match the original compilation options exactly.) > > regards, tom lane Alrighty. Here's what I got (assuming I did this right). My untrained eyes see some stuff regarding memory allocation. I wonder if overly aggressive memory related tweaks in the config file are causing the problem? I don't recall making any changes to the config file within a short time period of the problem starting, but let me know if I need to post any config settings. hostname:/var/lib/postgresql/8.1/mc-db2# gdb /usr/lib/postgresql/8.1/bin/postmaster core GNU gdb 6.4.90-debian Copyright (C) 2006 Free Software Foundation, Inc. GDB is free software, covered by the GNU General Public License, and you are welcome to change it and/or distribute copies of it under certain conditions. Type "show copying" to see the conditions. There is absolutely no warranty for GDB. Type "show warranty" for details. This GDB was configured as "i486-linux-gnu"...(no debugging symbols found) Using host libthread_db library "/lib/tls/i686/cmov/libthread_db.so.1". warning: Can't read pathname for load map: Input/output error. Reading symbols from /lib/libpam.so.0...(no debugging symbols found)...done. Loaded symbols for /lib/libpam.so.0 Reading symbols from /usr/lib/i686/cmov/libssl.so.0.9.8...(no debugging symbols found)...done. Loaded symbols for /usr/lib/i686/cmov/libssl.so.0.9.8 Reading symbols from /usr/lib/i686/cmov/libcrypto.so.0.9.8...(no debugging symbols found)...done. Loaded symbols for /usr/lib/i686/cmov/libcrypto.so.0.9.8 Reading symbols from /usr/lib/libkrb5.so.3...(no debugging symbols found)...done. Loaded symbols for /usr/lib/libkrb5.so.3 Reading symbols from /lib/libcom_err.so.2...(no debugging symbols found)...done. Loaded symbols for /lib/libcom_err.so.2 Reading symbols from /lib/tls/i686/cmov/libcrypt.so.1... (no debugging symbols found)...done. Loaded symbols for /lib/tls/i686/cmov/libcrypt.so.1 Reading symbols from /lib/tls/i686/cmov/libdl.so.2...(no debugging symbols found)...done. Loaded symbols for /lib/tls/i686/cmov/libdl.so.2 Reading symbols from /lib/tls/i686/cmov/libm.so.6...(no debugging symbols found)...done. Loaded symbols for /lib/tls/i686/cmov/libm.so.6 Reading symbols from /lib/tls/i686/cmov/libc.so.6...(no debugging symbols found)...done. Loaded symbols for /lib/tls/i686/cmov/libc.so.6 Reading symbols from /usr/lib/libz.so.1...(no debugging symbols found)...done. Loaded symbols for /usr/lib/libz.so.1 Reading symbols from /usr/lib/libk5crypto.so.3... (no debugging symbols found)...done. Loaded symbols for /usr/lib/libk5crypto.so.3 Reading symbols from /lib/tls/i686/cmov/libresolv.so.2...(no debugging symbols found)...done. Loaded symbols for /lib/tls/i686/cmov/libresolv.so.2 Reading symbols from /lib/ld-linux.so.2...(no debugging symbols found)...done. Loaded symbols for /lib/ld-linux.so.2 Reading symbols from /usr/lib/libkrb5support.so.0...(no debugging symbols found)...done. Loaded symbols for /usr/lib/libkrb5support.so.0 (no debugging symbols found) Core was generated by `postgres: autovacuum process mc_dairyqueen '. Program terminated with signal 11, Segmentation fault. #0 0x0827441d in MemoryContextAlloc () (gdb) bt #0 0x0827441d in MemoryContextAlloc () #1 0x08274467 in MemoryContextStrdup () #2 0x0826501c in database_getflatfilename () #3 0x0826504e in database_getflatfilename () #4 0x08265ec1 in AtEOXact_UpdateFlatFiles () #5 0x080a9111 in RecordTransactionCommit () #6 0x080a93a7 in CommitTransactionCommand () #7 0x081a6c3b in autovac_stopped () #8 0x081a75cd in autovac_start () #9 0x081ae33c in ClosePostmasterPorts () #10 0x081af058 in PostmasterMain () #11 0x0816b3e2 in main ()
Justin Pasher <justinp@newmediagateway.com> writes:
> Program terminated with signal 11, Segmentation fault.
> #0 0x0827441d in MemoryContextAlloc ()
> (gdb) bt
> #0 0x0827441d in MemoryContextAlloc ()
> #1 0x08274467 in MemoryContextStrdup ()
> #2 0x0826501c in database_getflatfilename ()
> #3 0x0826504e in database_getflatfilename ()
> #4 0x08265ec1 in AtEOXact_UpdateFlatFiles ()
> #5 0x080a9111 in RecordTransactionCommit ()
> #6 0x080a93a7 in CommitTransactionCommand ()
> #7 0x081a6c3b in autovac_stopped ()
> #8 0x081a75cd in autovac_start ()
> #9 0x081ae33c in ClosePostmasterPorts ()
> #10 0x081af058 in PostmasterMain ()
> #11 0x0816b3e2 in main ()
Hmm. This isn't very trustworthy for lack of debug symbols (what we're
probably looking at are the nearest global function names before the
actual locations). However, it strongly suggests that something is
broken in the active memory context, and the most likely explanations
for that are either a memory clobber (eg overrunning the requested size
of a chunk) or CurrentMemoryContext pointing at a context that was
already freed. The latter theory ties into the fact that it seems to be
happening during transaction end. But any such bug of either type
should have been found years ago given that development is invariably
done with CLOBBER_FREED_MEMORY enabled.
Alvaro, any thoughts? Remember this is 8.1.15.
Justin, if you do feel like recompiling, please do so with original
configure options (run pg_config to verify) and add --enable-cassert
as well as --enable-debug. That might give us more to work with.
regards, tom lane
Tom Lane wrote: > Hmm. This isn't very trustworthy for lack of debug symbols (what we're > probably looking at are the nearest global function names before the > actual locations). However, it strongly suggests that something is > broken in the active memory context, and the most likely explanations > for that are either a memory clobber (eg overrunning the requested size > of a chunk) or CurrentMemoryContext pointing at a context that was > already freed. The latter theory ties into the fact that it seems to be > happening during transaction end. But any such bug of either type > should have been found years ago given that development is invariably > done with CLOBBER_FREED_MEMORY enabled. > > Alvaro, any thoughts? Remember this is 8.1.15. Not really. It seems like this must be happening on the vicinity of process_whole_db(), which is a less used code path than do_autovacuum(), so it's more likely to have bugs. I don't see anything obviously wrong though. I note that process_whole_db is not changing to AutovacMemCxt the way do_autovacuum() does, but I don't see any way that this could cause a problem. Hmm, vacuum() creates a new memory context under PortalContext, but I don't see that one set anywhere on the autovacuum path ... is that bogus? The lack of debug symbols makes this all mere guesses though. The backtrace did not make a lot of sense to me. -- Alvaro Herrera http://www.CommandPrompt.com/ PostgreSQL Replication, Consulting, Custom Development, 24x7 support
Alvaro Herrera <alvherre@commandprompt.com> writes:
> Tom Lane wrote:
>> Hmm. This isn't very trustworthy for lack of debug symbols (what we're
>> probably looking at are the nearest global function names before the
>> actual locations).
> The lack of debug symbols makes this all mere guesses though. The
> backtrace did not make a lot of sense to me.
I read it like this:
#0 0x0827441d in MemoryContextAlloc () <-- real
#1 0x08274467 in MemoryContextStrdup () <-- real
#2 0x0826501c in database_getflatfilename () <-- real
#3 0x0826504e in database_getflatfilename () <-- must be write_database_file
#4 0x08265ec1 in AtEOXact_UpdateFlatFiles () <-- real
#5 0x080a9111 in RecordTransactionCommit () <-- must be CommitTransaction
#6 0x080a93a7 in CommitTransactionCommand () <-- real
#7 0x081a6c3b in autovac_stopped () <-- must be process_whole_db
#8 0x081a75cd in autovac_start () <-- real
#9 0x081ae33c in ClosePostmasterPorts () <-- must be ServerLoop
#10 0x081af058 in PostmasterMain ()
#11 0x0816b3e2 in main ()
although this requires one or two leaps of faith about single-call
static functions getting inlined so that they don't produce a callstack
entry (in particular that must have happened to AutoVacMain). In any
case, it's very hard to see how MemoryContextAlloc would dump core
unless the method pointer of the context it was pointed to was
clobbered. So I'm pretty sure that's what happened, and now we must
work backwards to how it happened,
Justin, it's entirely possible that the only way we'll figure it out
is for a developer to go poking at the entrails. Are you in a position
to give Alvaro or me ssh access to your test machine?
regards, tom lane
Tom Lane wrote: > I read it like this: > > #0 0x0827441d in MemoryContextAlloc () <-- real > #1 0x08274467 in MemoryContextStrdup () <-- real > #2 0x0826501c in database_getflatfilename () <-- real > #3 0x0826504e in database_getflatfilename () <-- must be write_database_file > #4 0x08265ec1 in AtEOXact_UpdateFlatFiles () <-- real > #5 0x080a9111 in RecordTransactionCommit () <-- must be CommitTransaction > #6 0x080a93a7 in CommitTransactionCommand () <-- real > #7 0x081a6c3b in autovac_stopped () <-- must be process_whole_db > #8 0x081a75cd in autovac_start () <-- real > #9 0x081ae33c in ClosePostmasterPorts () <-- must be ServerLoop > #10 0x081af058 in PostmasterMain () > #11 0x0816b3e2 in main () > > although this requires one or two leaps of faith about single-call > static functions getting inlined so that they don't produce a callstack > entry (in particular that must have happened to AutoVacMain). In any > case, it's very hard to see how MemoryContextAlloc would dump core > unless the method pointer of the context it was pointed to was > clobbered. So I'm pretty sure that's what happened, and now we must > work backwards to how it happened, > > Justin, it's entirely possible that the only way we'll figure it out > is for a developer to go poking at the entrails. Are you in a position > to give Alvaro or me ssh access to your test machine? > > regards, tom lane > I'm currently working on recompiling Postgres with the new configure parameters. I'm trying to go the easier route by downloading the Debian source package, add the new options, compile, then install the package. Hopefully this will give the closest possible binary to the current one. Incidentally, the --enable-debug option is already set for the Debian package (I did have to add --enable-cassert though). I'll let you know once I get it up if things work properly. As far as access to the machine, I'll contact you off-list if I can work something out for that. The data is not overly sensitive, but it's still client data nonetheless. I'll try to make a copy of the cluster and try to reduce the database count and see if I can still duplicate the problem. Thanks. Justin Pasher
Tom Lane wrote:
> I read it like this:
>
> #0 0x0827441d in MemoryContextAlloc () <-- real
> #1 0x08274467 in MemoryContextStrdup () <-- real
> #2 0x0826501c in database_getflatfilename () <-- real
> #3 0x0826504e in database_getflatfilename () <-- must be write_database_file
> #4 0x08265ec1 in AtEOXact_UpdateFlatFiles () <-- real
> #5 0x080a9111 in RecordTransactionCommit () <-- must be CommitTransaction
> #6 0x080a93a7 in CommitTransactionCommand () <-- real
> #7 0x081a6c3b in autovac_stopped () <-- must be process_whole_db
> #8 0x081a75cd in autovac_start () <-- real
> #9 0x081ae33c in ClosePostmasterPorts () <-- must be ServerLoop
> #10 0x081af058 in PostmasterMain ()
> #11 0x0816b3e2 in main ()
>
> although this requires one or two leaps of faith about single-call
> static functions getting inlined so that they don't produce a callstack
> entry (in particular that must have happened to AutoVacMain). In any
> case, it's very hard to see how MemoryContextAlloc would dump core
> unless the method pointer of the context it was pointed to was
> clobbered. So I'm pretty sure that's what happened, and now we must
> work backwards to how it happened,
>
> Justin, it's entirely possible that the only way we'll figure it out
> is for a developer to go poking at the entrails. Are you in a position
> to give Alvaro or me ssh access to your test machine?
>
> regards, tom lane
OK. Here's an update on this.
I was able to reduce the database cluster down to just one real database
(aside from template0/1 and postgres) and I was still getting the
segfault. I was even able to delete all the data from a lot of the
sensitive tables and still get the segfault. At least this means it's
easier for me to give access to the DB now if need be.
I recompiled from the Debian source package and added --enable-cassert
(--enable-debug was already there). I replaced the Debian standard
packages with the recompiled versions and started up the cluster. Now it
is hitting a failure on one of the assert lines, and the log message is
a little different.
2009-01-16 15:24:48 CST LOG: transaction ID wrap limit is 1076038431,
limited by database "template1"
TRAP: BadArgument("!(((context) != ((void *)0) &&
(((((Node*)((context)))->type) == T_AllocSetContext))))", File:
"mcxt.c", Line: 502)
2009-01-16 15:24:52 CST LOG: autovacuum process (PID 7066) was
terminated by signal 6
2009-01-16 15:24:52 CST LOG: terminating any other active server processes
A new backtrace from the core dump is below, although it looks almost
identical to me.
------------------------------
hostname:/var/lib/postgresql/8.1# gdb
/usr/lib/postgresql/8.1/bin/postmaster mc-db2/core
GNU gdb 6.4.90-debian
Copyright (C) 2006 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain
conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB. Type "show warranty" for details.
This GDB was configured as "i486-linux-gnu"...(no debugging symbols found)
Using host libthread_db library "/lib/tls/i686/cmov/libthread_db.so.1".
warning: Can't read pathname for load map: Input/output error.
Reading symbols from /lib/libpam.so.0...(no debugging symbols found)...done.
Loaded symbols for /lib/libpam.so.0
Reading symbols from /usr/lib/i686/cmov/libssl.so.0.9.8...(no debugging
symbols found)...done.
Loaded symbols for /usr/lib/i686/cmov/libssl.so.0.9.8
Reading symbols from /usr/lib/i686/cmov/libcrypto.so.0.9.8...(no
debugging symbols found)...done.
Loaded symbols for /usr/lib/i686/cmov/libcrypto.so.0.9.8
Reading symbols from /usr/lib/libkrb5.so.3...(no debugging symbols
found)...done.
Loaded symbols for /usr/lib/libkrb5.so.3
Reading symbols from /lib/libcom_err.so.2...(no debugging symbols
found)...done.
Loaded symbols for /lib/libcom_err.so.2
Reading symbols from /lib/tls/i686/cmov/libcrypt.so.1...
(no debugging symbols found)...done.
Loaded symbols for /lib/tls/i686/cmov/libcrypt.so.1
Reading symbols from /lib/tls/i686/cmov/libdl.so.2...(no debugging
symbols found)...done.
Loaded symbols for /lib/tls/i686/cmov/libdl.so.2
Reading symbols from /lib/tls/i686/cmov/libm.so.6...(no debugging
symbols found)...done.
Loaded symbols for /lib/tls/i686/cmov/libm.so.6
Reading symbols from /lib/tls/i686/cmov/libc.so.6...(no debugging
symbols found)...done.
Loaded symbols for /lib/tls/i686/cmov/libc.so.6
Reading symbols from /usr/lib/libz.so.1...(no debugging symbols
found)...done.
Loaded symbols for /usr/lib/libz.so.1
Reading symbols from /usr/lib/libk5crypto.so.3...
(no debugging symbols found)...done.
Loaded symbols for /usr/lib/libk5crypto.so.3
Reading symbols from /lib/tls/i686/cmov/libresolv.so.2...(no debugging
symbols found)...done.
Loaded symbols for /lib/tls/i686/cmov/libresolv.so.2
Reading symbols from /lib/ld-linux.so.2...(no debugging symbols
found)...done.
Loaded symbols for /lib/ld-linux.so.2
Reading symbols from /usr/lib/libkrb5support.so.0...(no debugging
symbols found)...done.
Loaded symbols for /usr/lib/libkrb5support.so.0
(no debugging symbols found)
Core was generated by `postgres: autovacuum process
mc_itec '.
Program terminated with signal 6, Aborted.
#0 0xffffe410 in __kernel_vsyscall ()
(gdb) bt
#0 0xffffe410 in __kernel_vsyscall ()
#1 0xb7c37811 in raise () from /lib/tls/i686/cmov/libc.so.6
#2 0xb7c38fb9 in abort () from /lib/tls/i686/cmov/libc.so.6
#3 0x0828cdf3 in ExceptionalCondition ()
#4 0x082a8cd2 in MemoryContextAlloc ()
#5 0x082a8d67 in MemoryContextStrdup ()
#6 0x0829749c in database_getflatfilename ()
#7 0x082974ce in database_getflatfilename ()
#8 0x08298341 in AtEOXact_UpdateFlatFiles ()
#9 0x080bcc81 in RecordTransactionCommit ()
#10 0x080bcf8f in CommitTransactionCommand ()
#11 0x081cd1eb in autovac_stopped ()
#12 0x081cdbcd in autovac_start ()
#13 0x081d4c0c in ClosePostmasterPorts ()
#14 0x081d5968 in PostmasterMain ()
#15 0x0818bd22 in main ()
Justin Pasher
Justin Pasher <justinp@newmediagateway.com> writes:
> I recompiled from the Debian source package and added --enable-cassert
> (--enable-debug was already there). I replaced the Debian standard
> packages with the recompiled versions and started up the cluster. Now it
> is hitting a failure on one of the assert lines, and the log message is
> a little different.
> TRAP: BadArgument("!(((context) != ((void *)0) &&
> (((((Node*)((context)))->type) == T_AllocSetContext))))", File:
> "mcxt.c", Line: 502)
Well, that confirms the thought that the memory context is clobbered,
but we're not any closer to understanding why.
> #1 0xb7c37811 in raise () from /lib/tls/i686/cmov/libc.so.6
> #2 0xb7c38fb9 in abort () from /lib/tls/i686/cmov/libc.so.6
> #3 0x0828cdf3 in ExceptionalCondition ()
> #4 0x082a8cd2 in MemoryContextAlloc ()
> #5 0x082a8d67 in MemoryContextStrdup ()
> #6 0x0829749c in database_getflatfilename ()
> #7 0x082974ce in database_getflatfilename ()
> #8 0x08298341 in AtEOXact_UpdateFlatFiles ()
> #9 0x080bcc81 in RecordTransactionCommit ()
> #10 0x080bcf8f in CommitTransactionCommand ()
> #11 0x081cd1eb in autovac_stopped ()
> #12 0x081cdbcd in autovac_start ()
> #13 0x081d4c0c in ClosePostmasterPorts ()
> #14 0x081d5968 in PostmasterMain ()
> #15 0x0818bd22 in main ()
... and you've seemingly not managed to install the debug symbols where
gdb can find them.
regards, tom lane
Tom Lane wrote:
> Justin Pasher <justinp@newmediagateway.com> writes:
>
>> I recompiled from the Debian source package and added --enable-cassert
>> (--enable-debug was already there). I replaced the Debian standard
>> packages with the recompiled versions and started up the cluster. Now it
>> is hitting a failure on one of the assert lines, and the log message is
>> a little different.
>>
>> TRAP: BadArgument("!(((context) != ((void *)0) &&
>> (((((Node*)((context)))->type) == T_AllocSetContext))))", File:
>> "mcxt.c", Line: 502)
>>
>
> Well, that confirms the thought that the memory context is clobbered,
> but we're not any closer to understanding why.
>
>
>> #1 0xb7c37811 in raise () from /lib/tls/i686/cmov/libc.so.6
>> #2 0xb7c38fb9 in abort () from /lib/tls/i686/cmov/libc.so.6
>> #3 0x0828cdf3 in ExceptionalCondition ()
>> #4 0x082a8cd2 in MemoryContextAlloc ()
>> #5 0x082a8d67 in MemoryContextStrdup ()
>> #6 0x0829749c in database_getflatfilename ()
>> #7 0x082974ce in database_getflatfilename ()
>> #8 0x08298341 in AtEOXact_UpdateFlatFiles ()
>> #9 0x080bcc81 in RecordTransactionCommit ()
>> #10 0x080bcf8f in CommitTransactionCommand ()
>> #11 0x081cd1eb in autovac_stopped ()
>> #12 0x081cdbcd in autovac_start ()
>> #13 0x081d4c0c in ClosePostmasterPorts ()
>> #14 0x081d5968 in PostmasterMain ()
>> #15 0x0818bd22 in main ()
>>
>
> ... and you've seemingly not managed to install the debug symbols where
> gdb can find them.
>
> regards, tom lane
>
Dang it. I wonder why the --enable-debug option doesn't seem to actually
be enabling debug. :( For reference, here is the configure command that
the package uses according to the config.log (in case you spot anything
wrong).
/usr/src/postgres-8.1.15/postgresql-8.1-8.1.15/build-tree/postgresql-8.1.15/configure
--build=i486-linux-gnu --prefix=/usr --includedir=${prefix}/include
--mandir=${prefix}/share/man --infodir=${prefix}/share/info
--sysconfdir=/etc --localstatedir=/var
--libexecdir=${prefix}/lib/postgresql-8.1 --disable-maintainer-mode
--disable-dependency-tracking --srcdir=.
--mandir=${prefix}/share/postgresql/8.1/man
--with-docdir=${prefix}/share/doc/postgresql-doc-8.1
--datadir=${prefix}/share/postgresql/8.1
--bindir=${prefix}/lib/postgresql/8.1/bin
--includedir=${prefix}/include/postgresql/ --enable-nls
--enable-integer-datetimes --enable-thread-safety --enable-debug
--enable-cassert --disable-rpath --with-tcl --with-perl --with-python
--with-pam --with-krb5 --with-openssl --with-gnu-ld
--with-tclconfig=/usr/lib/tcl8.4 --with-tkconfig=/usr/lib/tk8.4
--with-includes=/usr/include/tcl8.4 --with-pgport=5432 CFLAGS=-g -Wall
-O2 -fPIC LDFLAGS=-Wl,--as-needed
I'm going to try a compile from scratch from the 8.1.15 source tarball
and see if I can get better results. I'll let you know (probably next
week). Thanks.
Justin Pasher
Justin Pasher wrote: > Dang it. I wonder why the --enable-debug option doesn't seem to actually > be enabling debug. :( For reference, here is the configure command that > the package uses according to the config.log (in case you spot anything > wrong). Maybe the executable is getting stripped? (I think it wouldn't show the function names in that case, but maybe this gives you an idea) -- Alvaro Herrera http://www.CommandPrompt.com/ PostgreSQL Replication, Consulting, Custom Development, 24x7 support
Tom Lane wrote:
>
>> #1 0xb7c37811 in raise () from /lib/tls/i686/cmov/libc.so.6
>> #2 0xb7c38fb9 in abort () from /lib/tls/i686/cmov/libc.so.6
>> #3 0x0828cdf3 in ExceptionalCondition ()
>> #4 0x082a8cd2 in MemoryContextAlloc ()
>> #5 0x082a8d67 in MemoryContextStrdup ()
>> #6 0x0829749c in database_getflatfilename ()
>> #7 0x082974ce in database_getflatfilename ()
>> #8 0x08298341 in AtEOXact_UpdateFlatFiles ()
>> #9 0x080bcc81 in RecordTransactionCommit ()
>> #10 0x080bcf8f in CommitTransactionCommand ()
>> #11 0x081cd1eb in autovac_stopped ()
>> #12 0x081cdbcd in autovac_start ()
>> #13 0x081d4c0c in ClosePostmasterPorts ()
>> #14 0x081d5968 in PostmasterMain ()
>> #15 0x0818bd22 in main ()
>
> ... and you've seemingly not managed to install the debug symbols where
> gdb can find them.
>
> regards, tom lane
OK. I recompiled from source (I didn't expect it to go so quickly and
smoothly) and it looks like I might have the correct info now. Here's
the new backtrace. Let me know if I still don't have it right. The
configure is below to (for reference).
./configure --disable-maintainer-mode --disable-dependency-tracking
--enable-nls --enable-integer-datetimes --enable-thread-safety
--enable-debug --enable-cassert --disable-rpath --with-tcl --with-perl
--with-python --with-pam --with-krb5 --with-openssl --with-gnu-ld
--with-tclconfig=/usr/lib/tcl8.4 --with-tkconfig=/usr/lib/tk8.4
--with-includes=/usr/include/tcl8.4
------------------------------
postgres@hostname:/usr/local/pgsql/bin$ gdb
/usr/local/pgsql/bin/postmaster /var/lib/postgresql/8.1/mc-db2/core
GNU gdb 6.4.90-debian
Copyright (C) 2006 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain
conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB. Type "show warranty" for details.
This GDB was configured as "i486-linux-gnu"...Using host libthread_db
library "/lib/tls/i686/cmov/libthread_db.so.1".
warning: Can't read pathname for load map: Input/output error.
Reading symbols from /lib/libpam.so.0...done.
Loaded symbols for /lib/libpam.so.0
Reading symbols from /usr/lib/i686/cmov/libssl.so.0.9.8...done.
Loaded symbols for /usr/lib/i686/cmov/libssl.so.0.9.8
Reading symbols from /usr/lib/i686/cmov/libcrypto.so.0.9.8...done.
Loaded symbols for /usr/lib/i686/cmov/libcrypto.so.0.9.8
Reading symbols from /usr/lib/libkrb5.so.3...done.
Loaded symbols for /usr/lib/libkrb5.so.3
Reading symbols from /usr/lib/libz.so.1...done.
Loaded symbols for /usr/lib/libz.so.1
Reading symbols from /lib/libreadline.so.5...done.
Loaded symbols for /lib/libreadline.so.5
Reading symbols from /lib/tls/i686/cmov/libcrypt.so.1...done.
Loaded symbols for /lib/tls/i686/cmov/libcrypt.so.1
Reading symbols from /lib/tls/i686/cmov/libresolv.so.2...done.
Loaded symbols for /lib/tls/i686/cmov/libresolv.so.2
Reading symbols from /lib/tls/i686/cmov/libnsl.so.1...done.
Loaded symbols for /lib/tls/i686/cmov/libnsl.so.1
Reading symbols from /lib/tls/i686/cmov/libdl.so.2...done.
Loaded symbols for /lib/tls/i686/cmov/libdl.so.2
Reading symbols from /lib/tls/i686/cmov/libm.so.6...done.
Loaded symbols for /lib/tls/i686/cmov/libm.so.6
Reading symbols from /lib/tls/i686/cmov/libc.so.6...done.
Loaded symbols for /lib/tls/i686/cmov/libc.so.6
Reading symbols from /lib/libcom_err.so.2...done.
Loaded symbols for /lib/libcom_err.so.2
Reading symbols from /usr/lib/libk5crypto.so.3...done.
Loaded symbols for /usr/lib/libk5crypto.so.3
Reading symbols from /lib/libncurses.so.5...done.
Loaded symbols for /lib/libncurses.so.5
Reading symbols from /lib/ld-linux.so.2...done.
Loaded symbols for /lib/ld-linux.so.2
Reading symbols from /usr/lib/libkrb5support.so.0...done.
Loaded symbols for /usr/lib/libkrb5support.so.0
Core was generated by `postgres: autovacuum process
mc_itec '.
Program terminated with signal 6, Aborted.
#0 0xffffe410 in __kernel_vsyscall ()
(gdb) bt
#0 0xffffe410 in __kernel_vsyscall ()
#1 0xb7b1d811 in raise () from /lib/tls/i686/cmov/libc.so.6
#2 0xb7b1efb9 in abort () from /lib/tls/i686/cmov/libc.so.6
#3 0x0825f4a1 in ExceptionalCondition (conditionName=0x8324b6c
"!(((context) != ((void *)0) && (((((Node*)((context)))->type) ==
T_AllocSetContext))))",
errorType=0x82885e0 "BadArgument", fileName=0x8319d04 "mcxt.c",
lineNumber=502) at assert.c:51
#4 0x0827869e in MemoryContextAlloc (context=0x838e42c, size=19) at
mcxt.c:502
#5 0x0827872c in MemoryContextStrdup (context=0x838e42c,
string=0x8318833 "global/pg_database") at mcxt.c:655
#6 0x08268a4c in database_getflatfilename () at flatfiles.c:112
#7 0x08268a63 in write_database_file (drel=0x0, startup=6 '\006') at
flatfiles.c:194
#8 0x082697f2 in AtEOXact_UpdateFlatFiles (isCommit=1 '\001') at
flatfiles.c:815
#9 0x080b6741 in CommitTransaction () at xact.c:1470
#10 0x080b6a29 in CommitTransactionCommand () at xact.c:2184
#11 0x081b0f42 in AutoVacMain (argc=<value optimized out>, argv=<value
optimized out>) at autovacuum.c:559
#12 0x081b1879 in autovac_start () at autovacuum.c:174
#13 0x081b7f78 in ServerLoop () at postmaster.c:1269
#14 0x081b8bad in PostmasterMain (argc=3, argv=0x836b508) at
postmaster.c:943
#15 0x08175609 in main (argc=3, argv=0x836b508) at main.c:265
Justin Pasher
I wrote:
> ... and you've seemingly not managed to install the debug symbols where
> gdb can find them.
But never mind that --- it turns out to be trivial to reproduce the
crash. Just create a database, set its datfrozenxid and datvacuumxid
far in the past (via a manual update of pg_database), enable autovacuum,
and wait a bit.
What is happening is that autovacuum_do_vac_analyze contains
old_cxt = MemoryContextSwitchTo(AutovacMemCxt);
...
vacuum(vacstmt, relids);
...
MemoryContextSwitchTo(old_cxt);
and at the time it is called by process_whole_db, CurrentMemoryContext
points at TopTransactionContext. Which gets destroyed because vacuum()
internally finishes that transaction and starts a new one. When we
come out of vacuum(), CurrentMemoryContext again points at
TopTransactionContext, but *its not the same one*. The closing
MemoryContextSwitchTo is installing a stale pointer, which then remains
active into CommitTransaction. It's a wonder this code ever works.
The other path through do_autovacuum() escapes this fate because it
enters autovacuum_do_vac_analyze with CurrentMemoryContext pointing
at AutovacMemCxt, which isn't going to go away.
I argue that autovacuum_do_vac_analyze shouldn't attempt to restore the
caller's memory context at all. One possible approach is to make it
re-select AutovacMemCxt at exit, but I wonder if we shouldn't define
its entry and exit conditions as current context being
(the current instance of) TopTransactionContext.
It looks like 8.3 and HEAD take the latter approach and are therefore
safe from this bug. 8.2 seems to escape it also because it doesn't have
process_whole_db anymore, but it's certainly not
autovacuum_do_vac_analyze fault that it's not broken, because it's still
trying to restore a context that it has no right to assume still exists.
Alvaro, you want to take charge of fixing this?
regards, tom lane
Tom Lane wrote: > What is happening is that autovacuum_do_vac_analyze contains > > old_cxt = MemoryContextSwitchTo(AutovacMemCxt); > ... > vacuum(vacstmt, relids); > ... > MemoryContextSwitchTo(old_cxt); > > and at the time it is called by process_whole_db, CurrentMemoryContext > points at TopTransactionContext. Which gets destroyed because vacuum() > internally finishes that transaction and starts a new one. When we > come out of vacuum(), CurrentMemoryContext again points at > TopTransactionContext, but *its not the same one*. The closing > MemoryContextSwitchTo is installing a stale pointer, which then remains > active into CommitTransaction. It's a wonder this code ever works. Hmm, in retrospect this is pretty obviously buggy. I can't say that it's that easy for me to reproduce it though; I definitely can't make it crash. Maybe by sheer luck, the new TopTransactionContext pointer points to the same memory area that the old was stored in. I think this patch should fix it. Justin, would you try it and report back? I would commit it right away since it seems simple enough, but since I can't reproduce the crash, I prefer external confirmation first :-) -- Alvaro Herrera http://www.CommandPrompt.com/ PostgreSQL Replication, Consulting, Custom Development, 24x7 support
Attachment
On Fri, Jan 16, 2009 at 05:13:17PM -0600, Justin Pasher wrote: > Dang it. I wonder why the --enable-debug option doesn't seem to actually > be enabling debug. :( For reference, here is the configure command that > the package uses according to the config.log (in case you spot anything > wrong). For future reference, if you want debug symbols in your debian packages you need to build with DEB_BUILD_OPTIONS=nostrip in the environment. You can also remove the reference to dh_strip in the build file. Have a nice day, -- Martijn van Oosterhout <kleptog@svana.org> http://svana.org/kleptog/ > Please line up in a tree and maintain the heap invariant while > boarding. Thank you for flying nlogn airlines.
Attachment
Alvaro Herrera <alvherre@commandprompt.com> writes:
> Hmm, in retrospect this is pretty obviously buggy. I can't say that
> it's that easy for me to reproduce it though; I definitely can't make it
> crash. Maybe by sheer luck, the new TopTransactionContext pointer
> points to the same memory area that the old was stored in.
Yeah, there could be some platform dependency involved. I'm guessing
different structs that happen to fall into the same palloc size category
on one platform but not another.
Anyway, it happens consistently on my HP box. I find that your proposed
patch fixes it, but makes the "normal" path crash :-( --- the loop in
do_autovacuum has to be executed in AutovacMemCxt, because it creates an
Oid List that gets passed to vacuum() and had better not be in a
transaction-lifetime context. The attached modified patch works for me.
regards, tom lane
Index: autovacuum.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/postmaster/autovacuum.c,v
retrieving revision 1.5.2.8
diff -c -r1.5.2.8 autovacuum.c
*** autovacuum.c 17 Jan 2008 23:47:07 -0000 1.5.2.8
--- autovacuum.c 17 Jan 2009 15:31:05 -0000
***************
*** 925,937 ****
bool freeze)
{
VacuumStmt *vacstmt;
- MemoryContext old_cxt;
/*
* The node must survive transaction boundaries, so make sure we create it
* in a long-lived context
*/
! old_cxt = MemoryContextSwitchTo(AutovacMemCxt);
vacstmt = makeNode(VacuumStmt);
--- 925,936 ----
bool freeze)
{
VacuumStmt *vacstmt;
/*
* The node must survive transaction boundaries, so make sure we create it
* in a long-lived context
*/
! MemoryContextSwitchTo(AutovacMemCxt);
vacstmt = makeNode(VacuumStmt);
***************
*** 957,963 ****
vacuum(vacstmt, relids);
pfree(vacstmt);
! MemoryContextSwitchTo(old_cxt);
}
/*
--- 956,964 ----
vacuum(vacstmt, relids);
pfree(vacstmt);
!
! /* Make sure we end up pointing to the long-lived context at exit */
! MemoryContextSwitchTo(AutovacMemCxt);
}
/*
> -----Original Message----- > From: Tom Lane [mailto:tgl@sss.pgh.pa.us] > Sent: Saturday, January 17, 2009 9:50 AM > To: Alvaro Herrera > Cc: Justin Pasher; pgsql-general@postgresql.org > Subject: Re: [GENERAL] Autovacuum daemon terminated by signal 11 > > Alvaro Herrera <alvherre@commandprompt.com> writes: > > Hmm, in retrospect this is pretty obviously buggy. I can't say that > > it's that easy for me to reproduce it though; I definitely can't make it > > crash. Maybe by sheer luck, the new TopTransactionContext pointer > > points to the same memory area that the old was stored in. > > Yeah, there could be some platform dependency involved. I'm guessing > different structs that happen to fall into the same palloc size category > on one platform but not another. > > Anyway, it happens consistently on my HP box. I find that your proposed > patch fixes it, but makes the "normal" path crash :-( --- the loop in > do_autovacuum has to be executed in AutovacMemCxt, because it creates an > Oid List that gets passed to vacuum() and had better not be in a > transaction-lifetime context. The attached modified patch works for me. > > regards, tom lane I tried both Alvaro's patch and your patch, and I actually got the same results from both. I didn't experience a crash when autovacuum kicked in or when manually performing a vacuum on the database (if that's what you meant by the "normal path"). At any rate, everything seems to be working properly for me with the patch. Thanks! Justin Pasher
"Justin Pasher" <justinp@newmediagateway.com> writes:
>> From: Tom Lane [mailto:tgl@sss.pgh.pa.us]
>> Anyway, it happens consistently on my HP box. I find that your proposed
>> patch fixes it, but makes the "normal" path crash :-( --- the loop in
>> do_autovacuum has to be executed in AutovacMemCxt, because it creates an
>> Oid List that gets passed to vacuum() and had better not be in a
>> transaction-lifetime context. The attached modified patch works for me.
> I tried both Alvaro's patch and your patch, and I actually got the same
> results from both.
Alvaro's patch would most likely not crash in a non-assert-enabled
build, since the list wouldn't be physically damaged when the containing
context got freed. But obviously that's a risky thing ...
regards, tom lane
Tom Lane wrote: > Anyway, it happens consistently on my HP box. I find that your proposed > patch fixes it, but makes the "normal" path crash :-( --- the loop in > do_autovacuum has to be executed in AutovacMemCxt, because it creates an > Oid List that gets passed to vacuum() and had better not be in a > transaction-lifetime context. The attached modified patch works for me. Committed this patch to both 8.1 and 8.2. Thanks. -- Alvaro Herrera http://www.CommandPrompt.com/ PostgreSQL Replication, Consulting, Custom Development, 24x7 support