A PostgreSQL megállt és nem hajlandó elindulni. A szervernaplóban az alábbi mondat tölti el aggodalommal a DBA-t:
HINT: This probably means that some data is corrupted and you will have to use the last backup for recovery.
Mit jelent ez, mikor történhet ilyen, és mi a teendő ilyenkor?
Vizsgáljunk meg két esetet. Az lesz bennük a közös, hogy mindkét esetben összeomlik az adatbázis-szerver. Az első esetben a szerver automatikusan helyreállítja magát, a második esetben viszont nem.
Az első eset egy összeomlás utáni sikeres helyreállítás lesz.
Vizsgáljuk meg először az PostgreSQL szervert még az összeomlás előtt, futó állapotban.
A PostgreSQL szerver fontos része az ún. kontrollfájl, ami a szerver állapotáról szolgál információkkal.
A pg_controldata parancssoros eszközzel tudunk belenézni a kontrollfájlba. A parancs paramétereként az adatkönyvtár helyét kell megadni, amit általában a $PGDATA környezeti változó tartalmaz.
postgres@test ~]$ pg_controldata $PGDATA | grep REDO
Latest checkpoint’s REDO location: 0/9000110
Latest checkpoint’s REDO WAL file: 000000010000000000000009
A fenti kimenetben csak a REDO-val kapcsolatos sorokat szűrtük ki.t
A REDO location az pozíció WAL-ban, ahol a legutolsó checkpoint kezdődött, és ahonnan egy összeomlást követően a helyreállítást (recovery) kezdeni kell. Esetünkben ez a pozíció a 0/9000110. A második sorban pedig azt látjuk, hogy a 9-es WAL-szegmensben található ez a bizonyos pozíció.
A checkpoint egy olyan művelet, amely során minden adatváltoztatás kiíródik a memóriából az adatfájlokba. Tehát egy checkpoint azt jelenti, hogy addig a pontig biztos minden változtatást tartalmaznak az adatfájlok, ezért a helyreállítást elég ez után a pont után végrehajtani.
A pg_controldata kimenetében láthatjuk azt is, hogy a szerver milyen módbaban fut.
[postgres@test ~]$ pg_controldata $PGDATA | grep state
Database cluster state: in production
A state az adatbázis-szerver működési módját mutatja. Az in production a normál működés.
A fenti állapotban összeomlik a szerver valamilyen okból (crash). A következő indításkor az adatbázis-szerver automatikusan helyreállítja magát, ez az ún. automatic recovery vagy crash recovery.
Hogyan történik ez? Amikor az összeomlást követően elindítjuk a PostgreSQL szervert, akkor a szerver a kontroll fájlban azt látja magáról, hogy in production módban fut, ami lehetetlen, mert nem fut, hiszen épp most indul. Ebből jön rá a szerver, hogy nem lett szabályosan leállítva, automatikus helyreállítást kell indítani.
A sikeres crash recovery így néz ki a szervernaplóban:
2023-05-11 19:38:04.015 CEST [35300] LOG: database system was not properly shut down; automatic recovery in progress
2023-05-11 19:38:04.029 CEST [32894] LOG: redo starts at 0/9000110
2023-05-11 19:38:04.029 CEST [32894] LOG: invalid record length at 0/90001F8: wanted 24, got 0
2023-05-11 19:38:04.029 CEST [32894] LOG: redo done at 0/90001C0 system usage: …
2023-05-11 19:38:04.047 CEST [32892] LOG: checkpoint starting: end-of-recovery immediate wait
2023-05-11 19:38:04.079 CEST [32892] LOG: checkpoint complete: wrote 3 buffers (0.0%) …
2023-05-11 19:38:04.091 CEST [32889] LOG: database system is ready to accept connections
A szervernaplóban látszik, hogy nem lett szabályosan, konzisztens módon leállítva a szerver (not properly shut down), ezért automatikus helyreállítás fut (automatic recovery in progress).
Látszi a naplóban az is, hogy a helyreállítás a fent már látott ponton kezdődik a WAL-ból (redo starts at 0/9000110). Az invalid record length… üzenet ignorálható. A naplórészlet utolsó három sorában pedig azt látjuk, hogy történik egy checkpoint, és utána elindul a szerver normál módban.
Checkpoint többféle okból és többféle módon történhet. Esetünkben a WAL-ból történt recovery befejezéseként (end-of-recovery), a lehető leggyorsabb (immediate) checkpoint történik, és a szerver vár, amíg az be nem fejeződik (wait). Ez a checkpoint lényegében ugyanolyan, mint ami akkor történik, ha szabályosan állítjuk le az PostgreSQL-szervert.
(A szervernapló tartalmához egy megjegyzés: a log_checkpoints nevű szerverparaméter beállítása dönti el, hogy a checkpoint-eseményeket naplózza-e a szerver. Ez a paraméter a PostgreSQL 14-es verziójáig alapértelmezetten off értékre volt állítva, a 15-ös verziótól kezdve viszont ez megváltozott, és most már on az alapértelmezett értéke. Tehát csak a 15-ös verziótól kezdve naplózza automatikusan a szerver a checkpoint-eseményeket.)
A checkpoint adatait a szerver bejegyzi a kontrollfájlba és a WAL-ba is.
A WAL-fájlokba a pg_waldump nevű, parancssoros eszközzel tudunk bepillantani:
[postgres@test ~]$ pg_waldump $PGDATA/pg_wal/000000010000000000000009 | tail -n2
…
CHECKPOINT_SHUTDOWN redo 0/90001F8; …
A parancs kimenetében látható, hogy a fájl végén ott a bejegyzés egy olyan checkpointról, ami a szerver leállítása során is történik.
A kontrollfájlban is ugyanezt az információt látjuk:
[postgres@test ~]$ pg_controldata $PGDATA | grep REDO
Latest checkpoint’s REDO location: 0/90001F8
Latest checkpoint’s REDO WAL file: 000000010000000000000009
A checkpoint után a szerver elindul, mintha mi sem történt volna, és most indulna normálisan.
A második esetben szintén összeomlik az adatbázis-szerver, ám az automatikus helyreállítás nem sikerül.
A kontrollfájlban, közvetlenül az összeomlás előtt, az alábbi adatok voltak:
[postgres@test ~]$ pg_controldata $PGDATA | grep REDO
Latest checkpoint’s REDO location: 0/1F0012D0
Latest checkpoint’s REDO WAL file: 00000001000000000000001F
[postgres@test ~]$ pg_controldata $PGDATA | grep state
Database cluster state: in production
Ebben az állapotban történt az összeomlás. A szervernaplót megvizgálva láthatjuk, hogy az előző esethet hasonlóan ugyanúgy indul egy crash recovery az utolsó checkpointtól (REDO location: 0/1F0012D0).
2023-05-11 21:15:36.786 CEST [35300] LOG: database system was not properly shut down; automatic recovery in progress
2023-05-11 21:15:36.792 CEST [35300] LOG: redo starts at 0/1F0012D0
2023-05-11 21:15:36.793 CEST [35300] LOG: redo done at 0/25000110 …
2023-05-11 21:15:36.805 CEST [35300] FATAL: could not write to file „pg_wal/xlogtemp.35300”: No space left on device
2023-05-11 21:15:36.807 CEST [35052] LOG: startup process (PID 35300) exited with exit code 1
2023-05-11 21:15:36.808 CEST [35052] LOG: terminating any other active server processes
2023-05-11 21:15:36.809 CEST [35052] LOG: shutting down due to startup process failure
2023-05-11 21:15:36.813 CEST [35052] LOG: database system is shut down
A recovery ebben az esetben is befejeződik (redo done) a WAL 0/25000110 pontján, ami a WAL vége.
A legutolsó WAL-fájl a 25-ös szegmens:
[postgres@test ~]$ ls -lrt $PGDATA/pg_wal/
total 114688
-rw——-. 1 postgres postgres 16777216 May 11 21:14 000000010000000000000021
-rw——-. 1 postgres postgres 16777216 May 11 21:15 000000010000000000000022
-rw——-. 1 postgres postgres 16777216 May 11 21:15 000000010000000000000023
-rw——-. 1 postgres postgres 16777216 May 11 21:15 000000010000000000000024
-rw——-. 1 postgres postgres 16777216 May 11 21:15 000000010000000000000025
drwx——. 2 postgres postgres 180 May 11 21:15 archive_status
Ebben a WAL-szegmensfáljban a legutolsó bejegyzés a 0/25000110:
[postgres@test ~]$ pg_waldump $PGDATA/pg_wal/000000010000000000000025 | tail -n1
rmgr: XLOG len (rec/tot): 24/ 24, tx: 0, lsn: 0/25000110, prev 0/250000E8, desc: SWITCH
Tehát tényleg végigment a recovery, de csak a memóriában. Hiszen a recovery folyamat végén nem történt checkpoint. Ennek pedig az oka az, hogy a checkpoint tényét a WAL-ba is be kell jegyeznie a szervernek, de ezt nem tudja megtenni, mert a WAL-t nem tudja írni (could not write to file „pg_wal/xlogtemp.35300”), mivel nincs több hely a lemezen (No space left on device). (Egy új WAL-fájl írása úgy történik, hogy először egy ideiglenes xlogtemp fájlba íródnak az adatok, és ha ez sikerül, akkor nevezi át a szegmensnek megfelelő névre a fájlt a szerver.)
A szerver tehát a crash recovery folyamatot záró checkpoint előtt, helyhiány miatt megint összeomlik, mielőtt még el tudna indulni.
Checkpoint hiányában viszont sajnos nem lehetünk benne biztosak, hogy minden változtatás kiíródott-e az adatfájlokba.
Mivel nincs új checkpoint, a kontrollfájlban is ugyanaz checkpoint információ maradt, mint ami az előző indításkor volt:
[postgres@test ~]$ pg_controldata $PGDATA | grep REDO
Latest checkpoint’s REDO location: 0/1F0012D0
Latest checkpoint’s REDO WAL file: 00000001000000000000001F
Viszont a szerver most más módban van:
[postgres@test ~]$ pg_controldata $PGDATA | grep state
Database cluster state: in crash recovery
Ez érthető, hiszen crash recovery volt folyamatban legutoljára.
Ha a fenti állapotban megint elindítjuk az adatbázis-szervert, akkor most azt látja magáról a szerver, hogy in crash recovery módban fut. Ez megint csak lehetetlen, hiszen épp most indul a szerver. Ez tehát azt jelenti, hogy crash recovery közben volt egy újabb crash. Ezt a tényt be is jegyzi a szervernaplóba a szerver. Beleír továbbá egy általános megjegyzést is, hogy ez esetleg korrupciót is jelenthet:
2023-05-11 21:23:48.065 CEST [35401] LOG: database system was interrupted while in recovery at 2023-05-11 21:15:36 CEST
2023-05-11 21:23:48.065 CEST [35401] HINT: This probably means that some data is corrupted and you will have to use the last backup for recovery.
2023-05-11 21:23:48.073 CEST [35300] LOG: redo starts at 0/1F0012D0
2023-05-11 21:23:48.083 CEST [35300] LOG: redo done at 0/25000110 …
Az esetleges korrupcióra vonatkozó megjegyzés egy általános megjegyzés, mert a crash recovery többféle okból is félbeszakadhat. Esetünkben egyszerűen a helyhiány volt az oka, de lehetett volna az is, hogy ténylegesen korrupt adatok vannak a WAL-ban. A szerver az okot nem jegyzi föl magának, csak a kontrollfájlban lévő információ áll a rendelkezésére.
Esetünkben tehát a DBA megnyugodhat, nincs gond. A recovery pontosan ugyanonnan elindul, mint az előbb, és ha a crash recovery végén a checkpoint is meg tud történni, azzal a helyreállítás teljes. Ezután el fog indulni a szerver (in production), és az adatok konzisztensek lesznek. Csak biztosítanunk kell, hogy legyen elegendő hely a WAL-fájloknak.
A PostgreSQL-szever összeomlásának nagyon gyakori oka a WAL-terület betelése, de ez már egy következő bejegyzés témája.