Re: BUG #5151: autovacuum process segfaults when max_fsm_pages are too low

The following bug has been logged online:

Bug reference: 5151
Logged by: Boris Folgmann
Email address: boris(at)folgmann(dot)de
PostgreSQL version: 8.1.15
Operating system: CentOS release 4.8 (Final)
Description: autovacuum process segfaults when max_fsm_pages are too
low
Details:

Hi (SELECT * FROM pgsql_developers),

first of all I want to tell you, that I'm successfully using pgsql since
2002, v7.x on RedHat Linux for a high-speed mobile web application. I hardly
can remember problems caused by bugs in pgsql. I love it, it rocks. Thanks
for all!

Currently I'm using postgresql-8.1.15-1.el4s1.1 from the centosplus
repository for CentOS 4.8. All updates applied, kernel is
2.6.9-89.0.11.ELsmp.
I know that 8.1.18 is out, but haven't found something in the release-notes
about problems with max_fsm_pages. Anyway, there isn't any more recent RPM
available at the moment.

8.1.15 is in use since a month, server uptime was 7 days when yesterday
pgsql suffered from severe problems.

Relevant parts of postgresql.conf
------------------------------------------
max_fsm_pages = 60000 # 3x default
max_fsm_relations = 2000 # 2x default
vacuum_cost_delay = 125
autovacuum = on
------------------------------------------

Then suddenly during normal operation (sorry, German log):
------------------------------------------
2009-10-29 16:30:51 UTC @ [22311] LOG: Autovacuum: bearbeite Datenbank
»postgres«
2009-10-29 16:31:19 UTC @ [22311] HINWEIS: Anzahl der benötigten
Page-Slots (107264) überschreitet max_fsm_pages (60000)
2009-10-29 16:31:19 UTC @ [22311] TIPP: Erhöhen Sie eventuell den
Konfigurationsparameter »max_fsm_pages« auf über 107264.
2009-10-29 16:31:19 UTC @ [22311] LOG: Anzahl der benötigten Page-Slots
(107264) überschreitet max_fsm_pages (60000)
2009-10-29 16:31:19 UTC @ [22311] TIPP: Erhöhen Sie eventuell den
Konfigurationsparameter »max_fsm_pages« auf über 107264.
2009-10-29 16:31:19 UTC @ [22311] LOG: Grenze für
Transaktionsnummernüberlauf ist 2146954493, begrenzt durch Datenbank
»boris«
2009-10-29 16:31:19 UTC @ [3538] LOG: Autovacuum-Prozess (PID 22311) wurde
von Signal 11 beendet
2009-10-29 16:31:19 UTC @ [3538] LOG: aktive Serverprozesse werden
abgebrochen
2009-10-29 16:31:19 UTC modwars(at)modwars-vf-de [32243] WARNUNG: breche
Verbindung ab wegen Absturz eines anderen Serverprozesses
2009-10-29 16:31:19 UTC modwars(at)modwars-vf-de [32243] DETAIL: Der
Postmaster hat diesen Serverprozess angewiesen, die aktuelle Transaktion
zurückzurollen und die Sitzung zu beenden, weil ein anderer Serverprozess
abnormal beendet wurde und möglicherweise das Shared Memory verfälscht
hat.
2009-10-29 16:31:19 UTC modwars(at)modwars-vf-de [32243] TIPP: In einem Moment
sollten Sie wieder mit der Datenbank verbinden und Ihren Befehl wiederholen
können.
2009-10-29 16:31:19 UTC modwars(at)modwars-vf-de-2 [29075] WARNUNG: breche
Verbindung ab wegen Absturz eines anderen Serverprozesses
2009-10-29 16:31:19 UTC modwars(at)modwars-vf-de-2 [29075] DETAIL: Der
Postmaster hat diesen Serverprozess angewiesen, die aktuelle Transaktion
zurückzurollen und die Sitzung zu beenden, weil ein anderer Serverprozess
abnormal beendet wurde und möglicherweise das Shared Memory verfälscht
hat.
2009-10-29 16:31:19 UTC modwars(at)modwars-vf-de-2 [29075] TIPP: In einem
Moment sollten Sie wieder mit der Datenbank verbinden und Ihren Befehl
wiederholen können.

[...]

2009-10-29 16:31:19 UTC @ [3538] LOG: alle Serverprozesse beendet;
initialisiere neu
2009-10-29 16:31:19 UTC @ [22313] LOG: Datenbanksystem wurde am 2009-10-29
16:30:48 UTC unterbrochen
2009-10-29 16:31:19 UTC @ [22313] LOG: Checkpoint-Eintrag ist bei
671/7140CC68
2009-10-29 16:31:19 UTC @ [22313] LOG: Redo-Eintrag ist bei 671/7140CB88;
Undo-Eintrag ist bei 0/0; Shutdown FALSE
2009-10-29 16:31:19 UTC @ [22313] LOG: nächste Transaktions-ID:
1609954434; nächste OID: 3582936
2009-10-29 16:31:19 UTC @ [22313] LOG: nächste MultiXactId: 1583322;
nächster MultiXactOffset: 3674272
2009-10-29 16:31:19 UTC @ [22313] LOG: Datenbanksystem wurde nicht richtig
heruntergefahren; automatische Wiederherstellung läuft
2009-10-29 16:31:19 UTC @ [22313] LOG: Redo beginnt bei 671/7140CB88
2009-10-29 16:31:20 UTC @ [22313] LOG: Datensatz mit Länge null bei
671/71A1B48C
2009-10-29 16:31:20 UTC @ [22313] LOG: Redo fertig bei 671/71A1B464
2009-10-29 16:31:20 UTC @ [22313] LOG: Datenbanksystem ist bereit
2009-10-29 16:31:20 UTC @ [22313] LOG: Grenze für
Transaktionsnummernüberlauf ist 2146921242, begrenzt durch Datenbank
»postgres«
2009-10-29 16:31:25 UTC [unbekannt](at)[unbekannt] [22337] LOG: Verbindung
empfangen: Host=127.0.0.1 port=33743
2009-10-29 16:31:25 UTC modwars(at)modwars-vf-de [22337] LOG: Verbindung
authorisiert: Benutzer=modwars Datenbank=modwars-vf-de
2009-10-29 16:31:25 UTC [unbekannt](at)[unbekannt] [22340] LOG: Verbindung
empfangen: Host=127.0.0.1 port=33752
2009-10-29 16:31:25 UTC modwars(at)modwars-vf-de [22340] LOG: Verbindung
authorisiert: Benutzer=modwars Datenbank=modwars-vf-de

[...]

2009-10-29 16:32:22 UTC @ [22390] LOG: Autovacuum: bearbeite Datenbank
»postgres«
2009-10-29 16:32:44 UTC @ [22390] LOG: Grenze für
Transaktionsnummernüberlauf ist 2146954493, begrenzt durch Datenbank
»boris«
2009-10-29 16:32:44 UTC @ [3538] LOG: Autovacuum-Prozess (PID 22390) wurde
von Signal 11 beendet
2009-10-29 16:32:44 UTC @ [3538] LOG: aktive Serverprozesse werden
abgebrochen
2009-10-29 16:32:44 UTC modwars(at)modwars-vf-de-2 [22391] WARNUNG: breche
Verbindung ab wegen Absturz eines anderen Serverprozesses
2009-10-29 16:32:44 UTC modwars(at)modwars-vf-de-2 [22391] DETAIL: Der
Postmaster hat diesen Serverprozess angewiesen, die aktuelle Transaktion
zurückzurollen und die Sitzung zu beenden, weil ein anderer Serverprozess
abnormal beendet wurde und möglicherweise das Shared Memory verfälscht
hat.
2009-10-29 16:32:44 UTC modwars(at)modwars-vf-de-2 [22391] TIPP: In einem
Moment sollten Sie wieder mit der Datenbank verbinden und Ihren Befehl
wiederholen können.

[...]

2009-10-29 16:32:45 UTC @ [3538] LOG: alle Serverprozesse beendet;
initialisiere neu
2009-10-29 16:32:45 UTC @ [22394] LOG: Datenbanksystem wurde am 2009-10-29
16:32:02 UTC unterbrochen
2009-10-29 16:32:45 UTC @ [22394] LOG: Checkpoint-Eintrag ist bei
671/71A1B48C
2009-10-29 16:32:45 UTC @ [22394] LOG: Redo-Eintrag ist bei 671/71A1B48C;
Undo-Eintrag ist bei 0/0; Shutdown TRUE
2009-10-29 16:32:45 UTC @ [22394] LOG: nächste Transaktions-ID:
1609957422; nächste OID: 3582936
2009-10-29 16:32:45 UTC @ [22394] LOG: nächste MultiXactId: 1583322;
nächster MultiXactOffset: 3674272
2009-10-29 16:32:45 UTC @ [22394] LOG: Datenbanksystem wurde nicht richtig
heruntergefahren; automatische Wiederherstellung läuft
2009-10-29 16:32:45 UTC @ [22394] LOG: Redo beginnt bei 671/71A1B4D0
2009-10-29 16:32:45 UTC @ [22394] LOG: Datensatz mit Länge null bei
671/72572144
2009-10-29 16:32:45 UTC @ [22394] LOG: Redo fertig bei 671/7257211C
2009-10-29 16:32:45 UTC @ [22394] LOG: Datenbanksystem ist bereit
2009-10-29 16:32:45 UTC @ [22394] LOG: Grenze für
Transaktionsnummernüberlauf ist 2146921242, begrenzt durch Datenbank
»postgres«
2009-10-29 16:32:47 UTC [unbekannt](at)[unbekannt] [22398] LOG: Verbindung
empfangen: Host=127.0.0.1 port=34163
2009-10-29 16:32:47 UTC modwars(at)modwars-vf-de [22398] LOG: Verbindung
authorisiert: Benutzer=modwars Datenbank=modwars-vf-de
2009-10-29 16:32:47 UTC [unbekannt](at)[unbekannt] [22399] LOG: Verbindung
empfangen: Host=127.0.0.1 port=34177
2009-10-29 16:32:47 UTC modwars(at)modwars-vf-de [22399] LOG: Verbindung
authorisiert: Benutzer=modwars Datenbank=modwars-vf-de

[...]

2009-10-29 16:33:56 UTC @ [22481] LOG: Autovacuum: bearbeite Datenbank
»postgres«
2009-10-29 16:34:17 UTC @ [22481] LOG: Grenze für
Transaktionsnummernüberlauf ist 2146954493, begrenzt durch Datenbank
»boris«
2009-10-29 16:34:17 UTC @ [3538] LOG: Autovacuum-Prozess (PID 22481) wurde
von Signal 11 beendet
2009-10-29 16:34:17 UTC @ [3538] LOG: aktive Serverprozesse werden
abgebrochen
2009-10-29 16:34:17 UTC modwars(at)modwars-vf-de-2 [22418] WARNUNG: breche
Verbindung ab wegen Absturz eines anderen Serverprozesses
2009-10-29 16:34:17 UTC modwars(at)modwars-vf-de-2 [22418] DETAIL: Der
Postmaster hat diesen Serverprozess angewiesen, die aktuelle Transaktion
zurückzurollen und die Sitzung zu beenden, weil ein anderer Serverprozess
abnormal beendet wurde und möglicherweise das Shared Memory verfälscht
hat.
2009-10-29 16:34:17 UTC modwars(at)modwars-vf-de-2 [22418] TIPP: In einem
Moment sollten Sie wieder mit der Datenbank verbinden und Ihren Befehl
wiederholen können.

[...]

2009-10-29 16:34:17 UTC @ [3538] LOG: alle Serverprozesse beendet;
initialisiere neu
2009-10-29 16:34:17 UTC @ [22490] LOG: Datenbanksystem wurde am 2009-10-29
16:32:45 UTC unterbrochen
2009-10-29 16:34:17 UTC @ [22490] LOG: Checkpoint-Eintrag ist bei
671/72572144
2009-10-29 16:34:17 UTC @ [22490] LOG: Redo-Eintrag ist bei 671/72572144;
Undo-Eintrag ist bei 0/0; Shutdown TRUE
2009-10-29 16:34:17 UTC @ [22490] LOG: nächste Transaktions-ID:
1609964727; nächste OID: 3582936
2009-10-29 16:34:17 UTC @ [22490] LOG: nächste MultiXactId: 1583322;
nächster MultiXactOffset: 3674272
2009-10-29 16:34:17 UTC @ [22490] LOG: Datenbanksystem wurde nicht richtig
heruntergefahren; automatische Wiederherstellung läuft
2009-10-29 16:34:17 UTC @ [22490] LOG: Redo beginnt bei 671/72572188
2009-10-29 16:34:18 UTC @ [22490] LOG: Datensatz mit Länge null bei
671/72CDBF58
2009-10-29 16:34:18 UTC @ [22490] LOG: Redo fertig bei 671/72CDBF30
2009-10-29 16:34:18 UTC @ [22490] LOG: Datenbanksystem ist bereit
2009-10-29 16:34:18 UTC @ [22490] LOG: Grenze für
Transaktionsnummernüberlauf ist 2146921242, begrenzt durch Datenbank
»postgres«
2009-10-29 16:34:19 UTC [unbekannt](at)[unbekannt] [22497] LOG: Verbindung
empfangen: Host=127.0.0.1 port=34443
2009-10-29 16:34:19 UTC modwars(at)modwars-vf-de-2 [22497] LOG: Verbindung
authorisiert: Benutzer=modwars Datenbank=modwars-vf-de-2
2009-10-29 16:34:21 UTC [unbekannt](at)[unbekannt] [22499] LOG: Verbindung
empfangen: Host=127.0.0.1 port=34482
2009-10-29 16:34:21 UTC modwars(at)modwars-vf-de [22499] LOG: Verbindung
authorisiert: Benutzer=modwars Datenbank=modwars-vf-de

[...]
------------------------------------------

As autovacuum kept crashing, the Java webapp was no longer working.

-> Restarting postmaster with fsm options raised to 10x default didn't help.
Though the new value was a lot larger than the one proposed in the logfile.
------------------------------------------
max_fsm_pages = 200000
max_fsm_relations = 10000
------------------------------------------

Finally I could resolve the problem by turning off autovacuum, disabling all
client connections and running VACUUM ANALYZE; manually on all data bases.
After that, autovacuum was again working and I could resume normal
operation. As far as I understand the documentation about max_fsm_pages a
value too low should never lead to problems like this.
So I hope you can find the cause of this incident and fix it in future
versions.

Best regards,
boris

Boris Folgmann wrote:
> Currently I'm using postgresql-8.1.15-1.el4s1.1 from the centosplus
> repository for CentOS 4.8. All updates applied, kernel is
> 2.6.9-89.0.11.ELsmp.
> I know that 8.1.18 is out, but haven't found something in the release-notes
> about problems with max_fsm_pages. Anyway, there isn't any more recent RPM
> available at the moment.

I don't think this is related to fsm, actually. Seems like something in
autovacuum, and there was this fix in 8.1.16 (from the release notes):

Fix crash in autovacuum (Alvaro)

The crash occurs only after vacuuming a whole database for
anti-transaction-wraparound purposes, which means that it occurs
infrequently and is hard to track down.

So I would suggest upgrading. If that doesn't help, and you can
reproduce the issue, a backtrace from a core dump would be nice.

--
Heikki Linnakangas
EnterpriseDB http://www.enterprisedb.com

"Boris Folgmann" <boris(at)folgmann(dot)de> writes:
> Currently I'm using postgresql-8.1.15-1.el4s1.1 from the centosplus
> repository for CentOS 4.8. All updates applied, kernel is
> 2.6.9-89.0.11.ELsmp.
> I know that 8.1.18 is out, but haven't found something in the release-notes
> about problems with max_fsm_pages. Anyway, there isn't any more recent RPM
> available at the moment.

Red Hat stopped supporting the RHEL-4 App Stack product awhile ago;
since CentOS is evidently copying that, you should not hold your
breath waiting for an update :-(. However, as far as I can see
the RHEL-5 SRPM should be completely compatible with RHEL-4 ---
so just grab the 8.1.18 SRPM from RHEL-5 and rebuild it locally.
Or use Devrim's RPMs from postgresql.org (I think he has a build
of 8.1.x for RHEL-4, though I could be wrong).

regards, tom lane

On Fri, 2009-10-30 at 17:35 -0400, Tom Lane wrote:
> I think he has a build of 8.1.x for RHEL-4, though I could be wrong).

Yes, we have:
http://yum.pgsqlrpms.org/8.1/redhat/rhel-4-x86_64/repoview/
http://yum.pgsqlrpms.org/8.1/redhat/rhel-4-i386/repoview/

Boris, repo howto is here:

http://yum.pgsqlrpms.org/howtoyum.php

Regards,
--
Devrim GÜNDÜZ, RHCE
Command Prompt - http://www.CommandPrompt.com
devrim~gunduz.org, devrim~PostgreSQL.org, devrim.gunduz~linux.org.tr
http://www.gunduz.org Twitter: http://twitter.com/devrimgunduz

Hi Tom,

Tom Lane schrieb/wrote:
> > Red Hat stopped supporting the RHEL-4 App Stack product awhile ago;
> > since CentOS is evidently copying that, you should not hold your
> > breath waiting for an update :-(. However, as far as I can see

It seems that you are right, and I don't understand how they can stop
releasing important updates as RHEL4 is still supported.

> > Or use Devrim's RPMs from postgresql.org (I think he has a build
> > of 8.1.x for RHEL-4, though I could be wrong).

I've done that on 10 Nov 2009 and they're working perfectly. No autovac
crashes since then.
RedHat is very conservative concerning pgsql as my small table shows:

RHEL/CentOS 4.x 5.x
pgsql default 7.4 8.1
pgsql RHWAS 8.1 8.2

So I'm feeling very happy at the moment using your yum repositories and are
thinking about using an even more recent postgresql version in the future.
Is 8.4.1 ready for production or is it advisable to wait for one or two
updates?

tnx,
boris

Boris Folgmann <boris(at)folgmann(dot)de> writes:
> Tom Lane schrieb/wrote:
>> Red Hat stopped supporting the RHEL-4 App Stack product awhile ago;
>> since CentOS is evidently copying that, you should not hold your
>> breath waiting for an update :-(. However, as far as I can see

> It seems that you are right, and I don't understand how they can stop
> releasing important updates as RHEL4 is still supported.

They EOL'd the App Stack product. I'm not too happy about it either,
but I don't get to make those decisions.

> Is 8.4.1 ready for production or is it advisable to wait for one or two
> updates?

8.4.1 is pretty stable AFAICT, though if you're feeling conservative
you might want to wait for 8.4.2 (next month sometime). In any case
you'd want to do some compatibility testing with your apps before
updating your production DB. Jumping from 8.1.x to 8.4.x is almost
certain to hit a change or two.

regards, tom lane