MyWiki

Ez az oldal csak olvasható. Megtekintheted a forrását, de nem változtathatod meg. Ha úgy gondolod, hogy ez helytelen, kérdezd az Adminisztrátorokat!
====== Korrupt lett az adatbázis? ======

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.

===== 1. Sikeres helyreállítás összeomlás után =====
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.



===== 2. Sikertelen helyreállítás összeomlás után =====
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.