Postgres - Streaming Replication: requested WAL segment ... has already been removed

greystone

Active Member
Hi,

ist jetzt kein aktuelles dringendes Problem. Aber vielleicht ist das ja für den ein oder anderen interessant.

Ich habe hier einen PostgreSQL 9.3 Server (Die Version ist EOL 2018 - ist mir bekannt. Kommentare diesbezüglich helfen mir nicht weiter. Es liegt nicht in meinem Verantwortungsbereich, das ändern zu können.) mit ca. 1 TB Datenbankverzeichnis. Hier habe ich einen Primary und einen Hot-Standby-Server. Dabei habe ich WAL-Archivierung eingesetzt und hebe die WAL-Segmente 5 Tage auf. Ich führe täglich ein Basebackup (und Dumps aller DBs) durch.

Selten mal verliert der Standby-Server die Verbindung und ich muss den Datenbestand via BaseBackup und WAL-Recovery wieder herstellen. Das funktioniert am Anfang recht gut. Der Standby-Server holt sich nach und nach die WAL-Files aus dem Archiv und holt Stück für Stück zum Datenbestand des Primary auf. Irgendwann kommt dann die Meldung:

Code:
< 2024-06-29 22:42:55.522 UTC > LOG:  restored log file "000000010003D384000000AB" from archive
< 2024-06-29 22:42:55.537 UTC > DEBUG:  got WAL segment from archive
< 2024-06-29 22:42:55.537 UTC > LOG:  unexpected pageaddr 3D384/F2000000 in log segment 000000010003D384000000AB, offset 0
< 2024-06-29 22:42:55.570 UTC > LOG:  started streaming WAL from primary at 3D384/AA000000 on timeline 1
< 2024-06-29 22:42:55.571 UTC > FATAL:  could not receive data from WAL stream: ERROR:  requested WAL segment 000000010003D384000000AA has already been removed

Laut Internetrecherche ist die Meldung unexpected pageaddr die Information, dass der Standby jetzt von WAL-Recovery auf direkte Replikation zum Primary umstellt, wie die nächste Logzeile ja auch klar anzeigt. Das ist aber doof, weil das Segment 000000010003D384000000AB schon ca. 3 Stunden in der Vergangenheit liegt und der Primary das nicht mehr vorhält - deswegen dann die nächste Meldungszeile: Ätsch - WAL Segment already removed. Genau dafür ist ja das WAL-Archiv da, dass sich der Standby die WAL-Dateien genau dort her holt.

Als Workaround habe ich jetzt wal_keep_segments auf 10000 gesetzt. Das sind ca. 160 GB zusätzlich für 5 Stunden Transaktionshistorie. Aber auch das erfordert noch, dass ich bei einer Standby-Recovery extra direkt vorher das BaseBackup nochmal durchführen muss, weil sonst der Zeitabstand zu groß ist.

Ich verstehe nur nicht, warum der Standby-Server viel zu früh auf direkte Replikation zum Primary umschaltet, anstatt brav alles aus dem WAL-Archiv zu holen.

Was mir noch aufgefallen ist, ist, dass der Zeitstempel des archivierten und komprimierten WAL-Segments auf dem WAL-Archiv-Server deutlich später zu sein scheint, als der erste - scheinbar erfolgreiche - Abruf des gleichen WAL-Segments aus dem Archiv vom Hot-StandBy Server. Dafür ist die Information noch wichtig, dass ich die WAL-Segmente unkomprimiert auf den WAL-Archiv-Server kopiere und dort von mehreren paralellen Kompressorprozessen komprimieren lasse (xz -1 => verkleinert die Datei um 90%). Die Anzahl der unkomprimierten Dateien ist allerdings gering (jetzt bei ca. 15). Das könnte sich vielleicht irgendwann aufgestaut haben.

Das müsste also dann eigentlich einen Fehler verursacht haben, da das WAL-Segment ja eigentlich noch nicht im Archiv war. Hat es interessanterweise aber nicht. Und wenn ich den Postgres auf dem Standby-Server anhalte und erneut starte, holt der sich ca. 10 WAL-Segmente vorher, kommt dann wieder bei demjenigen an, was oben steht und schaltet dann wieder auf den Primary um, mit der gleichen obigen Meldung.

Verstehen tue ich das noch nicht so ganz. Ich habe nur den Verdacht, dass das mit der Kompression mir vielleicht in die Suppe spuckt.

Zur Info hier noch meine WAL-Einstellungen auf dem Primary ...

Code:
select name,setting from pg_settings where name like '%wal%';
             name             |   setting 
------------------------------+-------------
 max_wal_senders              | 20
 wal_block_size               | 8192
 wal_buffers                  | 2048
 wal_keep_segments            | 10000
 wal_level                    | hot_standby
 wal_receiver_status_interval | 10
 wal_receiver_timeout         | 60000
 wal_segment_size             | 2048
 wal_sender_timeout           | 60000
 wal_sync_method              | fdatasync
 wal_writer_delay             | 200

... und meine recovery.conf auf dem Standby-Server:

Code:
primary_conninfo = 'host=primaryserver.domain.tld port=5432 user=repl_user password=verysicherespasswort'
standby_mode = 'on'
restore_command = '/usr/local/bin/recover_wal_file "%f" "%p"'
 
Last edited:
Ich habe die Verzögerung der WAL-Dateiablage im Archiv durch die Komprimierung jetzt im Monitoring. Üblicherweise sind es 15 Minuten und geht in Lastspitzen hoch bis zu einer Stunde.
 
Back
Top