| Következő változat | Előző változat |
| it:postgres_user_group:cikkek:korrupt_lett_az_adatbazis [2023/07/30 21:33] – létrehozva rblst | it:postgres_user_group:cikkek:korrupt_lett_az_adatbazis [2023/07/30 21:56] (aktuális) – rblst |
|---|
| ====== Korrupt lett adatbázis? ====== | ====== 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: | A PostgreSQL megállt és nem hajlandó elindulni. A szervernaplóban az alábbi mondat tölti el aggodalommal a DBA-t: |
| 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. | 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 crash recovery ===== | ===== 1. Sikeres helyreállítás összeomlás után ===== |
| Az első eset egy összeomlás utáni sikeres helyreállítás lesz. | Az első eset egy összeomlás utáni sikeres helyreállítás lesz. |
| |
| |
| A PostgreSQL szerver fontos része az ún. kontrollfájl, ami a szerver állapotáról szolgál információkkal. | 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. | 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 | ''postgres@test ~]$ pg_controldata $PGDATA | grep REDO\\ |
| Latest checkpoint's REDO location: 0/9000110 | Latest checkpoint's REDO location: 0/9000110\\ |
| Latest checkpoint's REDO WAL file: 000000010000000000000009'' | Latest checkpoint's REDO WAL file: 000000010000000000000009'' |
| |
| A fenti kimenetben csak a REDO-val kapcsolatos sorokat szűrtük ki.t | 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 ''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 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. | A pg_controldata kimenetében láthatjuk azt is, hogy a szerver milyen módbaban fut. |
| |
| ''[postgres@test ~]$ pg_controldata $PGDATA | grep state | ''[postgres@test ~]$ pg_controldata $PGDATA | grep state\\ |
| Database cluster state: in production'' | 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 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. | 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. | 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: | 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.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: 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: 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.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.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.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'' | 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). | 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. | 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. | 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. |
| |
| Van egy log_checkpoints szerverparaméter, ami a PostgreSQL 14-es verzióig alapértelmezetten "off" értékre volt állítva, a 15-ös verziótól kezdve ez megváltozott, és már "on" az értéke alapértelmezetten. Tehát csak a 15-ös verziótól naplózza automatikusan a szerver a checkpoint eseményeket. | (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 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: | A WAL-fájlokba a ''pg_waldump'' nevű, parancssoros eszközzel tudunk bepillantani: |
| |
| ''[postgres@test ~]$ pg_waldump $PGDATA/pg_wal/000000010000000000000009 | tail -n2 | ''[postgres@test ~]$ pg_waldump $PGDATA/pg_wal/000000010000000000000009 | tail -n2\\ |
| ... | ...\\ |
| CHECKPOINT_SHUTDOWN redo 0/90001F8; ...'' | CHECKPOINT_SHUTDOWN redo 0/90001F8; ...'' |
| |
| A kontrollfájlban is ugyanezt az információt látjuk: | A kontrollfájlban is ugyanezt az információt látjuk: |
| |
| ''[postgres@test ~]$ pg_controldata $PGDATA | grep REDO | ''[postgres@test ~]$ pg_controldata $PGDATA | grep REDO\\ |
| Latest checkpoint's REDO location: 0/90001F8 | Latest checkpoint's REDO location: 0/90001F8\\ |
| Latest checkpoint's REDO WAL file: 000000010000000000000009'' | Latest checkpoint's REDO WAL file: 000000010000000000000009'' |
| |
| |
| |
| ===== 2. Sikertelen crash recovery ===== | ===== 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 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: | A kontrollfájlban, közvetlenül az összeomlás előtt, az alábbi adatok voltak: |
| |
| ''[postgres@test ~]$ pg_controldata $PGDATA | grep REDO | ''[postgres@test ~]$ pg_controldata $PGDATA | grep REDO\\ |
| Latest checkpoint's REDO location: 0/1F0012D0 | Latest checkpoint's REDO location: 0/1F0012D0\\ |
| Latest checkpoint's REDO WAL file: 00000001000000000000001F'' | Latest checkpoint's REDO WAL file: 00000001000000000000001F'' |
| |
| ''[postgres@test ~]$ pg_controldata $PGDATA | grep state | ''[postgres@test ~]$ pg_controldata $PGDATA | grep state\\ |
| Database cluster state: in production'' | 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). | 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.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.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.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.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.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.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.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'' | 2023-05-11 21:15:36.813 CEST [35052] LOG: database system is shut down'' |
| |
| |
| ''[postgres@test ~]$ ls -lrt $PGDATA/pg_wal/ | ''[postgres@test ~]$ ls -lrt $PGDATA/pg_wal/ |
| total 114688 | total 114688\\ |
| -rw-------. 1 postgres postgres 16777216 May 11 21:14 000000010000000000000021 | -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 000000010000000000000022\\ |
| -rw-------. 1 postgres postgres 16777216 May 11 21:15 000000010000000000000023 | -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 000000010000000000000024\\ |
| -rw-------. 1 postgres postgres 16777216 May 11 21:15 000000010000000000000025 | -rw-------. 1 postgres postgres 16777216 May 11 21:15 000000010000000000000025\\ |
| drwx------. 2 postgres postgres 180 May 11 21:15 archive_status'' | drwx------. 2 postgres postgres 180 May 11 21:15 archive_status'' |
| |
| Ebben a WAL-szegmensfáljban a legutolsó bejegyzés a 0/25000110: | Ebben a WAL-szegmensfáljban a legutolsó bejegyzés a 0/25000110: |
| |
| ''[postgres@test ~]$ pg_waldump $PGDATA/pg_wal/000000010000000000000025 | tail -n1 | ''[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'' | 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 nincsen checkpoint. Azért nem történt checkpoint, mert annak tényét a WAL-ba is be kellene jegyezni, azt viszont nem tudta elvégezni a szerver, mert a WAL-t nem tudta írni a szerver (''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). | 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. | 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. |
| Mivel nincs új checkpoint, a kontrollfájlban is ugyanaz checkpoint információ maradt, mint ami az előző indításkor volt: | 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 | ''[postgres@test ~]$ pg_controldata $PGDATA | grep REDO\\ |
| Latest checkpoint's REDO location: 0/1F0012D0 | Latest checkpoint's REDO location: 0/1F0012D0\\ |
| Latest checkpoint's REDO WAL file: 00000001000000000000001F'' | Latest checkpoint's REDO WAL file: 00000001000000000000001F'' |
| |
| Viszont a szerver most más módban van: | Viszont a szerver most más módban van: |
| |
| ''[postgres@test ~]$ pg_controldata $PGDATA | grep state | ''[postgres@test ~]$ pg_controldata $PGDATA | grep state\\ |
| Database cluster state: in crash recovery'' | Database cluster state: in crash recovery'' |
| |
| Ez érthető, hiszen crash recovery volt folyamatban legutoljára. | 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 van. Ez azt jelenti, hogy crash recovery közben volt egy újabb crash, ezt be is jegyzi a a szervernaplóba a szerver. Beleír továbbá egy általános megjegyzést is, hogy ez esetleg korrupciót is jelenthet: | 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] 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.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.073 CEST [35300] LOG: redo starts at 0/1F0012D0\\ |
| 2023-05-11 21:23:48.083 CEST [35300] LOG: redo done at 0/25000110 ...'' | 2023-05-11 21:23:48.083 CEST [35300] LOG: redo done at 0/25000110 ...'' |
| |
| Ez egy általános megjegyzés, mert a crash recovery többféle okból is crash-elhet. 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. | 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 nincs gond, a recovery pontosan ugyanonnan elindul, mint az előbb, és ha a recovery végén a checkpoint meg tud történni, azzal a recovery 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. | 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. | 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. |
