Moje pierwsze doświadczenie w przywracaniu bazy danych Postgres po awarii (nieprawidłowa strona w bloku 4123007 bazy relacion base/16490)

Chcę podzielić się z wami moim pierwszym udanym doświadczeniem przywracania pełnej funkcjonalności bazy danych Postgres. Z systemem zarządzania bazą danych Postgres zapoznałem się pół roku temu, wcześniej nie miałem żadnego doświadczenia w administracji bazami danych.

Pracuję jako pół inżynier DevOps w dużej firmy IT. Nasza firma zajmuje się rozwijaniem oprogramowania dla wysoko obciążonych serwisów, a ja odpowiadam za utrzymanie, wsparcie i wdrażanie. Przed mną postawiono standardowe zadanie: zaktualizować aplikację na jednym serwerze. Aplikacja została napisana w Django, w trakcie aktualizacji wykonywane są migracje (zmiana struktury bazy danych), a przed tym procesem wykonujemy pełny zrzut bazy danych za pomocą standardowego programu pg_dump na wszelki wypadek.

Podczas wykonywania zrzutu wystąpił nieoczekiwany błąd (wersja Postgres – 9.5):

pg_dump: Wydobycie zawartości tabeli "ws_log_smevlog" nie powiodło się: PQgetResult() nie powiodło się.
pg_dump: Komunikat o błędzie z serwera: BŁĄD: nieprawidłowa strona w bloku 4123007 bazy relacion base/16490/21396989
pg_dump: Komenda brzmi: COPY public.ws_log_smevlog [...]
pg_dump: [archiwizacja równoległa] proces roboczy zakończył się nieoczekiwanie

Błąd "nieprawidłowa strona w bloku" mówi o problemach na poziomie systemu plików, co jest bardzo niepokojące. Na różnych forach sugerowano wykonanie FULL VACUUM z opcją zero_damaged_pages aby rozwiązać ten problem. Cóż, spróbujmy…

Przygotowanie do przywrócenia

UWAGA! Zrób koniecznie kopię zapasową Postgres przed próbą przywrócenia bazy danych. Jeśli masz maszynę wirtualną, zatrzymaj bazę danych i wykonaj migawkę. Jeśli nie masz możliwości zrobienia migawki, zatrzymaj bazę i skopiuj zawartość katalogu Postgres (w tym pliki wal) w bezpieczne miejsce. Najważniejsze w naszym przypadku to nie pogorszyć sytuacji. Przeczytaj to.

Ponieważ ogólnie rzecz biorąc, baza działała, ograniczyłem się do zwykłego zrzutu bazy danych, ale wykluczyłem tabelę z uszkodzonymi danymi (opcja -T, —exclude-table=TABLE w pg_dump).

Serwer był fizyczny, więc wykonanie migawki było niemożliwe. Kopia zapasowa wykonana, idziemy dalej.

Sprawdzanie systemu plików

Przed próbą przywrócenia bazy danych należy upewnić się, że mamy wszystko w porządku z samym systemem plików. W przypadku błędów trzeba je naprawić, ponieważ w przeciwnym razie można tylko pogorszyć sytuację.

W moim przypadku system plików z bazą danych był zamontowany w "/srv" i typ był ext4.

Zatrzymujemy bazę danych: systemctl stop postgresql@9.5-main.service i sprawdzamy, czy system plików nie jest używany, aby można go było odmontować za pomocą komendy lsof:
lsof +D /srv

Musiałem również zatrzymać bazę danych redis, ponieważ również była używana "/srv". Dalej odmontowałem /srv (umount).

Sprawdzanie systemu plików zostało wykonane za pomocą narzędzia e2fsck z opcją -f (Wymusić sprawdzanie, nawet jeśli system plików jest oznaczony jako czysty):

Następnie za pomocą narzędzia dumpe2fs (sudo dumpe2fs /dev/mapper/gu2—sys-srv | grep checked) można upewnić się, że sprawdzenie rzeczywiście zostało przeprowadzone:

e2fsck informuje, że nie znaleziono problemów na poziomie systemu plików ext4, co oznacza, że możemy kontynuować próby odzyskania bazy danych, a dokładniej wrócić do vacuum full (oczywiście, konieczne jest ponowne zamontowanie systemu plików i uruchomienie bazy danych).

Jeśli masz serwer fizyczny, sprawdź stan dysków (poprzez smartctl -a /dev/XXX) lub kontrolera RAID, aby upewnić się, że problem nie leży na poziomie sprzętowym. W moim przypadku RAID był 'żelazny', dlatego poprosiłem lokalnego administratora o sprawdzenie stanu RAID (serwer był w kilku setkach kilometrów ode mnie). Powiedział, że nie ma błędów, co oznacza, że na pewno możemy rozpocząć odzyskiwanie.

Próba 1: zero_damaged_pages

Łączymy się z bazą przez psql kontem z prawami superużytkownika. Potrzebujemy właśnie superużytkownika, ponieważ tylko on może zmieniać opcję zero_damaged_pages . W moim przypadku to postgres:

psql -h 127.0.0.1 -U postgres -s [database_name]

Opcja zero_damaged_pages jest potrzebna, aby zignorować błędy odczytu (ze strony postgrespro):

Przy wykryciu uszkodzonego nagłówka strony Postgres Pro zazwyczaj zgłasza błąd i przerywa bieżącą transakcję. Jeśli parametr zero_damaged_pages jest włączony, zamiast tego system wydaje ostrzeżenie, zeruje uszkodzoną stronę w pamięci i kontynuuje przetwarzanie. To zachowanie niszczy dane, a dokładniej wszystkie wiersze na uszkodzonej stronie.

Włączamy opcję i próbujemy zrobić pełne vacuum tabeli:

VACUUM FULL VERBOSE

Niestety, niepowodzenie.

Napotkaliśmy podobny błąd:

INFO: vacuuming "“public.ws_log_smevlog”
WARNING: invalid page in block 4123007 of relation base/16400/21396989; zeroing out page
ERROR: unexpected chunk number 573 (expected 565) for toast value 21648541 in pg_toast_106070

pg_toast – mechanizm przechowywania 'długich danych' w Postgres, jeśli nie mieszczą się na jednej stronie (domyślnie 8kB).

Próba 2: reindex

Pierwsza porada z Google nie pomogła. Po kilku minutach poszukiwań znalazłem drugą poradę – zrobić reindeksowanie uszkodzonej tabeli. Tę poradę spotkałem w wielu miejscach, ale nie budziła zaufania. Zróbmy reindeksowanie:

reindex table ws_log_smevlog

reindeksowanie zakończyło się bez problemów.

Jednak to nie pomogło, VACUUM FULL zakończyło się awarią z podobnym błędem. Ponieważ przywykłem do niepowodzeń, postanowiłem poszukać dalej porad w internecie i natrafiłem na dość interesujący artykuł.

Próba 3: SELECT, LIMIT, OFFSET

W powyższym artykule sugerowano, aby przyjrzeć się tabeli wiersz po wierszu i usunąć problematyczne dane. Na początku trzeba było przejrzeć wszystkie wiersze:

for ((i=0; i /dev/null || echo $i; done

W moim przypadku tabela zawierała 1 628 991 wierszy! Właściwie należało zadbać o partycjonowanie danych, ale to temat na osobną dyskusję. Była sobota, uruchomiłem tę komendę w tmux i poszedłem spać:

for ((i=0; i /dev/null || echo $i; done

Rano postanowiłem sprawdzić, jak się sprawy mają. Ku mojemu zdziwieniu, odkryłem, że przez 20 godzin zeskanowano tylko 2% danych! Nie chciałem czekać 50 dni. Kolejna całkowita porażka.

Ale nie zamierzałem się poddawać. Zaciekawiło mnie, dlaczego skanowanie trwało tak długo. Z dokumentacji (znowu na postgrespro) dowiedziałem się:

OFFSET wskazuje, aby pominąć podaną liczbę wierszy, zanim zacznie zwracać wiersze.
Jeśli podano zarówno OFFSET, jak i LIMIT, najpierw system pomija wiersze OFFSET, a następnie zaczyna liczyć wiersze dla ograniczenia LIMIT.

Stosując LIMIT, ważne jest, aby używać również klauzuli ORDER BY, aby wyniki były zwracane w określonym porządku. W przeciwnym razie mogą być zwracane nieprzewidywalne podzbiory wierszy.

Jasne jest, że powyższe polecenie było błędne: po pierwsze, brakowało order by, wynik mógł być błędny. Po drugie, Postgres musiał najpierw zeskasować i pominąć wiersze OFFSET, a wraz ze wzrostem OFFSET wydajność malałaby jeszcze bardziej.

Próba 4: zrzut w formie tekstu

Następnie wpadłem na, wydawałoby się, genialny pomysł: zrobić zrzut w formie tekstu i przeanalizować ostatni zapisany wiersz.

Ale na początku zapoznajmy się ze strukturą tabeli ws_log_smevlog:

W naszym przypadku mamy kolumnę "id", który zawierał unikalny identyfikator (licznik) wiersza. Plan był taki:

1. Zaczynamy tworzenie zrzutu w formacie tekstowym (jako komendy SQL)
2. W pewnym momencie tworzenie zrzutu zostałoby przerwane z powodu błędu, ale plik tekstowy i tak zostałby zapisany na dysku
3. Sprawdzamy koniec pliku tekstowego, w ten sposób znajdujemy identyfikator (id) ostatniego wiersza, który został pomyślnie zgrany

Zacząłem tworzyć zrzut w formacie tekstowym:

pg_dump -U my_user -d my_database -F p -t ws_log_smevlog -f .\/my_dump.dump

Tworzenie zrzutu, jak się spodziewano, przerwało się z tym samym błędem:

pg_dump: Komunikat o błędzie z serwera: ERROR: invalid page in block 4123007 of relation base\/16490\/21396989

Następnie przez tail sprawdziłem koniec zrzutu (tail -5 .\/my_dump.dump) odkryłem, że zrzut przerwał się na wierszu z id 186 525. „To znaczy, problem leży w wierszu z id 186 526, on jest uszkodzony, trzeba go usunąć!” – pomyślałem. Ale, wykonując zapytanie do bazy danych:
«select * from ws_log_smevlog where id=186529okazało się, że z tym wierszem jest wszystko w porządku… Wiersze z indeksami 186 530 — 186 540 również działały bez problemów. Kolejny „genialny pomysł” się nie powiódł. Później zrozumiałem, dlaczego tak się stało: podczas usuwania lub zmiany danych w tabeli nie są one fizycznie usuwane, a oznaczane jako „martwe krotki”, a następnie przychodzi autovacuum i oznacza te wiersze jako usunięte, co pozwala na ponowne użycie tych wierszy. Dla zrozumienia, jeśli dane w tabeli się zmieniają i włączone jest autovacuum, to nie są one przechowywane w sposób sekwencyjny.

Próba 5: SELECT, FROM, WHERE id=

Niepowodzenia czynią nas silniejszymi. Nigdy nie należy się poddawać, trzeba iść do końca i wierzyć w siebie i swoje możliwości. Dlatego postanowiłem spróbować jeszcze jednej opcji: po prostu przeglądać wszystkie rekordy w bazie danych jeden po drugim. Znałem strukturę mojej tabeli (patrz wyżej), mamy pole id, które jest unikalne (klucz podstawowy). W tabeli mamy 1 628 991 wiersz i id są uporządkowane, co oznacza, że możemy po prostu przechodzić przez nie jeden po drugim:

for ((i=1; i<1628991; i=$((i+1)) )); do psql -U my_user -d my_database  -c "SELECT * FROM ws_log_smevlog where id=$i" >\/dev\/null || echo $i; done

Jeśli ktoś nie rozumie, polecenie działa w następujący sposób: przegląda tabelę wiersz po wierszu i wysyła stdout do /dev/null, ale jeśli polecenie SELECT kończy się niepowodzeniem, to wyświetla komunikat o błędzie (stderr jest wysyłany do konsoli) i zwraca wiersz, zawierający błąd (dzięki ||, co oznacza, że wystąpił problem z wyborem (kod zwrotu polecenia nie jest 0)).

Miałem szczęście, miałem utworzone indeksy na polu id:

Oznacza to, że znalezienie wiersza z odpowiednim identyfikatorem nie powinno zajmować dużo czasu. Teoretycznie powinno zadziałać. Cóż, uruchamiamy polecenie w tmux i idziemy spać.

Rano odkryłem, że przeglądnięto około 90 000 rekordów, co stanowi nieco ponad 5%. To świetny rezultat, biorąc pod uwagę poprzednią metodę (2%)! Ale nie chciało mi się czekać 20 dni…

Próba 6: SELECT, FROM, WHERE id >= i id <

Dla klienta do bazy danych przydzielono doskonały serwer: dwuprocesorowy Intel Xeon E5-2697 v2, w naszym zasięgu mieliśmy aż 48 wątków! Obciążenie serwera było średnie, bez większych problemów mogliśmy obsłużyć około 20 wątków. Pamięci RAM też było wystarczająco: aż 384 gigabajty!

Dlatego polecenie należało rozdzielić:

for ((i=1; i<1628991; i=$((i+1)) )); do psql -U my_user -d my_database  -c "SELECT * FROM ws_log_smevlog where id=$i" >\/dev\/null || echo $i; done

Można było napisać piękny i elegancki skrypt, ale wybrałem najszybszy sposób na równoległe przetwarzanie: ręczne podzielenie zakresu 0-1628991 na interwały po 100 000 rekordów i uruchomienie osobno 16 poleceń w postaci:

for ((i=N; i/dev/null || echo $i; done

Ale to nie wszystko. Teoretycznie połączenie z bazą danych również zajmuje trochę czasu i zasobów systemowych. Połączenie z 1 628 991 rekordami nie było zbyt rozsądne, zgódź się. Dlatego przy jednym połączeniu wydobądźmy 1000 wierszy zamiast jednego. W rezultacie polecenie przekształciło się w to:

for ((i=N; i=$i and id/dev/null || echo $i; done

Otwieramy 16 okien w sesji tmux i uruchamiamy polecenia:

1) for ((i=0; i=$i and id/dev/null || echo $i; done
2) for ((i=100000; i=$i and id/dev/null || echo $i; done
…
15) for ((i=1400000; i=$i and id/dev/null || echo $i; done
16) for ((i=1500000; i=$i and id/dev/null || echo $i; done

Po dniu otrzymałem pierwsze wyniki! A dokładnie (wartości XXX i ZZZ już się nie zachowały):

ERROR:  brakuje fragmentu numer 0 dla wartości toast 37837571 w pg_toast_106070
829000
ERROR:  brakuje fragmentu numer 0 dla wartości toast XXX w pg_toast_106070
829000
ERROR:  brakuje fragmentu numer 0 dla wartości toast ZZZ w pg_toast_106070
146000

To oznacza, że mamy trzy wiersze z błędem. ID pierwszego i drugiego problematycznego rekordu znajdowały się pomiędzy 829 000 a 830 000, natomiast ID trzeciego – pomiędzy 146 000 a 147 000. Następnie musieliśmy po prostu znaleźć dokładną wartość ID problematycznych rekordów. W tym celu przeglądamy nasz zakres z problematycznymi rekordami krokiem 1 i identyfikujemy ID:

for ((i=829000; i/dev/null || echo $i; done
829417
ERROR:  unexpected chunk number 2 (expected 0) for toast value 37837843 in pg_toast_106070
829449
for ((i=146000; i/dev/null || echo $i; done
829417
ERROR:  unexpected chunk number ZZZ (expected 0) for toast value XXX in pg_toast_106070
146911

Szczęśliwe zakończenie

Znaleźliśmy problematyczne wiersze. Łączymy się z bazą przez psql i próbujemy je usunąć:

my_database=# delete from ws_log_smevlog where id=829417;
DELETE 1
my_database=# delete from ws_log_smevlog where id=829449;
DELETE 1
my_database=# delete from ws_log_smevlog where id=146911;
DELETE 1

Ku mojemu zdziwieniu, rekordy usunęły się bez jakichkolwiek problemów, nawet bez opcji zero_damaged_pages.

Następnie połączyłem się z bazą, zrobiłem VACUUM FULL (myślę, że nie było to konieczne), i w końcu pomyślnie utworzyłem kopię zapasową za pomocą pg_dump. Zrzut wykonany bez żadnych błędów! Problem udało się rozwiązać w taki oto sposób. Radości nie było końca, po tylu niepowodzeniach znalazłem rozwiązanie!

Podziękowania i zakończenie

Oto jak wyglądało moje pierwsze doświadczenie przywracania rzeczywistej bazy danych Postgres. To doświadczenie zapamiętam na długo.

Na koniec chciałbym podziękować firmie PostgresPro za przetłumaczoną dokumentację na język polski i za całkowicie darmowe kursy online, które bardzo pomogły mi podczas analizy problemu.

Źródło: habr.com