BUG #5151: autovacuum process segfaults when max_fsm_pages are too low - Mailing list pgsql-bugs

The following bug has been logged online:

Bug reference:      5151
Logged by:          Boris Folgmann
Email address:      boris@folgmann.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@modwars-vf-de [32243] WARNUNG:  breche
Verbindung ab wegen Absturz eines anderen Serverprozesses
2009-10-29 16:31:19 UTC modwars@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@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@modwars-vf-de-2 [29075] WARNUNG:  breche
Verbindung ab wegen Absturz eines anderen Serverprozesses
2009-10-29 16:31:19 UTC modwars@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@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]@[unbekannt] [22337] LOG:  Verbindung
empfangen: Host=127.0.0.1 port=33743
2009-10-29 16:31:25 UTC modwars@modwars-vf-de [22337] LOG:  Verbindung
authorisiert: Benutzer=modwars Datenbank=modwars-vf-de
2009-10-29 16:31:25 UTC [unbekannt]@[unbekannt] [22340] LOG:  Verbindung
empfangen: Host=127.0.0.1 port=33752
2009-10-29 16:31:25 UTC modwars@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@modwars-vf-de-2 [22391] WARNUNG:  breche
Verbindung ab wegen Absturz eines anderen Serverprozesses
2009-10-29 16:32:44 UTC modwars@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@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]@[unbekannt] [22398] LOG:  Verbindung
empfangen: Host=127.0.0.1 port=34163
2009-10-29 16:32:47 UTC modwars@modwars-vf-de [22398] LOG:  Verbindung
authorisiert: Benutzer=modwars Datenbank=modwars-vf-de
2009-10-29 16:32:47 UTC [unbekannt]@[unbekannt] [22399] LOG:  Verbindung
empfangen: Host=127.0.0.1 port=34177
2009-10-29 16:32:47 UTC modwars@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@modwars-vf-de-2 [22418] WARNUNG:  breche
Verbindung ab wegen Absturz eines anderen Serverprozesses
2009-10-29 16:34:17 UTC modwars@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@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]@[unbekannt] [22497] LOG:  Verbindung
empfangen: Host=127.0.0.1 port=34443
2009-10-29 16:34:19 UTC modwars@modwars-vf-de-2 [22497] LOG:  Verbindung
authorisiert: Benutzer=modwars Datenbank=modwars-vf-de-2
2009-10-29 16:34:21 UTC [unbekannt]@[unbekannt] [22499] LOG:  Verbindung
empfangen: Host=127.0.0.1 port=34482
2009-10-29 16:34:21 UTC modwars@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