4 Minuten Lesezeit (848 Worte)

Kurz und gut – Episode #20 PostgreSQL: Sag mir quando, sag mir wann? Wie lange dauert mein PostgreSQL Recovery noch?

Dienstag, 25. Juni 2024

Immer wieder kommt es bei PostgreSQL zu der Frage, wie lange denn eine Recovery dauert. Sei es beim Hochfahren einer Instanz nach einem System-Crash oder nach der Wiederherstellung des Clusters aus einer Sicherung.

Wird beim Start diese Meldung ausgeben?

pg_ctl: server did not start in time

Wird bei der Anmeldung mit psql diese Meldung ausgegeben?

FATAL: the database system is starting up

In diesem Fall ist Ihre Datenbankinstanz vermutlich gerade im Recovery-Modus. Normalerweise dauert so ein Vorgang nur wenige Sekunden. Allerdings gibt es Ausnahmesituationen, in denen dies länger dauern kann. Eine Abfrage des aktuellen Zustandes über Systemkatalog-Tabellen ist in diesem Zustand leider nicht möglich. Auch die postgresql.log gibt in diesem Zusammenhang ungünstigerweise keinen Aufschluss über den Fortschritt.

Um während der Recovery trotzdem auf dem Laufenden zu bleiben, kann man sich mit dem Kommando pg_controldata einen Überblick über den momentanen Zustand des Clusters verschaffen. Dies ist eines der wenigen Kommandos, das auch funktioniert, wenn der Cluster (noch) nicht online ist.

Ausgabe (Auszug):

pg_control version number:            1300
Catalog version number:               202307071 
Database system identifier:           7364370724439948932 
Database cluster state:               in crash recovery 
pg_control last modified:             Fri 03 May 2024 09:38:53 AM CEST 
Latest checkpoint location:           2/96000188 
Latest checkpoint's REDO location:    2/96000188 
Latest checkpoint's REDO WAL file:    000000010000000200000096 
... 
Time of latest checkpoint:            Fri 03 May 2024 09:38:53 AM CEST 
...

Das zeigt uns zumindest an, dass der Cluster wiederhergestellt wird ("in crash recovery") und in welcher WAL-Datei der letzte Checkpoint stattgefunden hat ("Latest checkpoint's REDO WAL file"). An dieser Stelle erwartet man möglicherweise instinktiv eine Art Fortschrittsanzeige. Aber bis zum Abschuss des Recoverys wird sich an dieser Anzeige leider nichts ändern.

Als Nächstes werfen wir einen Blick in das Verzeichnis $PGDATA/pg_wal. Dort befinden sich alle wiederherzustellenden WALs, in der folgenden Ansicht nach Zeitpunkt absteigend sortiert:

[pg_wal]$ ls -lt 0* |(head;tail) 
-rw------- 1 postgres postgres 16777216 May  3 17:00 00000001000000060000001D 
-rw------- 1 postgres postgres 16777216 May  3 16:59 00000001000000060000001C 
-rw------- 1 postgres postgres 16777216 May  3 16:58 00000001000000060000001B 
-rw------- 1 postgres postgres 16777216 May  3 16:57 00000001000000060000001A 
-rw------- 1 postgres postgres 16777216 May  3 16:56 000000010000000600000019 
-rw------- 1 postgres postgres 16777216 May  3 16:55 000000010000000600000018 
-rw------- 1 postgres postgres 16777216 May  3 16:54 000000010000000600000017 
-rw------- 1 postgres postgres 16777216 May  3 16:53 000000010000000600000016 
-rw------- 1 postgres postgres 16777216 May  3 16:52 000000010000000600000015 
-rw------- 1 postgres postgres 16777216 May  3 16:51 000000010000000600000014 
... 
-rw------- 1 postgres postgres 16777216 May  3 09:40 00000001000000020000009F 
-rw------- 1 postgres postgres 16777216 May  3 09:40 00000001000000020000009E 
-rw------- 1 postgres postgres 16777216 May  3 09:40 00000001000000020000009D 
-rw------- 1 postgres postgres 16777216 May  3 09:40 00000001000000020000009C 
-rw------- 1 postgres postgres 16777216 May  3 09:40 00000001000000020000009B 
-rw------- 1 postgres postgres 16777216 May  3 09:40 00000001000000020000009A 
-rw------- 1 postgres postgres 16777216 May  3 09:40 000000010000000200000099 
-rw------- 1 postgres postgres 16777216 May  3 09:40 000000010000000200000098 
-rw------- 1 postgres postgres 16777216 May  3 09:40 000000010000000200000097 
-rw------- 1 postgres postgres 16777216 May  3 09:40 000000010000000200000096

Wir können Linux das Zählen überlassen:

[pg_wal]$ ls -ltr 0* | wc -l

Ergebnis: 904 WAL-Segmente müssen für die Recovery durchlaufen werden.

Das momentan in Recovery befindliche WAL-Segment finden wir mit einer der folgenden Methoden heraus.

Wenn PostgreSQL als Service gestartet wurde:

[pg_wal]$ sudo systemctl status postgresql-16.service 
● postgresql@16-main.service - PostgreSQL Cluster 16-main 
... 
             ├─703 /usr/lib/postgresql/16/bin/postgres -D /var/lib/postgresql/16/main -c config_file=/etc/postgresql/16/main/postgresql.conf 
             ├─704 postgres: 16/main: logger 
             └─705 postgres: 16/main: startup   recovering 00000001000000020000009B

Ansonsten kommt die letzte Zeile auch etwas weniger schön heraus, wenn wir eingeben:

[pg_wal]$ ps f -ef | grep postgres | grep startup | grep -v grep 
 

postgres    705    1 28 17:22 ?        Rs     0:00  |
                        \_ postgres: startup recovering 00000001000000020000009B

Nur den Dateinamen des aktuell verarbeiteten WAL-Segments bekommen wir so:

[pg_wal]$ pgrep -a postgres | grep startup | awk '{print $NF}

All diese Erkenntnisse können wir nun nutzen, um ein kleines Shell-Programm zu verfassen:

#!/bin/bash 
  
# Ermittele das WAL, das gerade eingespielt wird (das letzte Element in der Zeile) 
recwal=$(pgrep -a postgres | grep startup | awk '{print $NF}') 
  
# Überprüfen, ob recwal erfolgreich gesetzt wurde 
if [[ -z "$recwal" ]]; then 
    echo "Fehler: Konnte das eingespielte WAL nicht ermitteln." 
    exit 1 
fi 
  
# Initialisiere den Zähler 
count=0 
  
# Durchsuche die WALs absteigend sortiert und zähle die Dateien bis zum gesuchten WAL 
for wal in $(ls -t $PGDATA/pg_wal/0*); do 
    ((count++)) 
    if [[ "$wal" == *"$recwal"* ]]; then 
        echo "Noch $((count - 1)) WALs einzuspielen" 
        exit 0 
    fi 
done 
  
# Falls das WAL nicht gefunden wurde 
echo "Fehler: Das eingespielte WAL wurde in den WAL-Dateien nicht gefunden." 
exit 1

Wenn man das Skript alle paar Sekunden laufen lässt, erhält man eine Fortschrittsanzeige:

... 
Noch 894 WALs einzuspielen 
Noch 868 WALs einzuspielen 
Noch 842 WALs einzuspielen 
Noch 817 WALs einzuspielen 
Noch 793 WALs einzuspielen 
Noch 782 WALs einzuspielen 
...