Błąd usuwania PostgreSQL z „Błąd: próba usunięcia niewidocznej krotki”

25

Błąd

Próba usunięcia krotek zawierających nieprawidłowe znaczniki czasu za pomocą

DELETE FROM comments WHERE date > '1 Jan 9999' OR date < '1 Jan 2000' OR date_found > '1 Jan 9999' OR date_found < '1 Jan 2000';

kończy się w

ERROR:  attempted to delete invisible tuple

Istnieje lista mailingowa z 2009 roku omawiająca dokładnie ten sam komunikat o błędzie, w którym OP to naprawił, ale nie znajduję wyjaśnienia, jak to zrobił ani co mogło doprowadzić do tego błędu.

Jestem bezradny z powodu braku trafień w Google i mojej ograniczonej wiedzy o PostgreSQL.

Co doprowadziło do korupcji

Miałem serwer PostgreSQL 9.5.5 ( ~ 4 TB danych, wszystkie ustawienia domyślne, z wyjątkiem zwiększonych limitów pamięci ) działający na Debianie 8, kiedy jądro systemu operacyjnego spanikowało - prawdopodobnie podczas przebudowy / dev / md1, gdzie zlokalizowano swap. Wcześniej PostgreSQL zjadł prawie całe miejsce na dysku za pomocą pliku dziennika o pojemności 400 GB. System operacyjny nigdy nie uruchomił się ponownie, sprawdzanie dysku przebiegło poprawnie, więc uruchomiłem system z płyty LiveCD i na wszelki wypadek wykonałem kopię zapasową każdego urządzenia blokowego na obrazy. Pomyślnie przebudowałem katalog / z / dev / md2, fsck pokazał czysty system plików i utworzyłem kopię zapasową folderu PGDATA na zewnętrznym dysku twardym.

Co zrobiłem, aby spróbować odzyskać

Po sformatowaniu urządzeń MD i ponownej instalacji systemu operacyjnego wraz ze świeżym postgresql-9.5 zatrzymałem serwer PostgreSQL, przeniosłem folder PGDATA do użytkownika postgres i uruchomiłem serwer - wszystko wydawało się w porządku, nie było błędów.

Jak tylko zacząłem pg_dumpall, to umarło

Error message from server: ERROR:  timestamp out of range

Oczywiście próbowałem usunąć krotki, ale w końcu ciągle pojawiał się ten sam invisible tuplebłąd.

Rzeczy, których próbowałem

Po pierwsze, usuwanie zapytań nie powiodło się z powodu uszkodzonych stron, więc ustawiłem następujące ustawienia:

zero_damaged_pages = on
ignore_system_indexes = on
enable_indexscan = off
enable_bitmapscan = off
enable_indexonlyscan = off

Teraz zauważyłem, że kiedy ponownie uruchamiam te same zapytania, serwer ciągle zeruje te same strony, nie jestem pewien, co to znaczy:

invalid page in block 92800 of relation base/16385/16443; zeroing out page

Próbowałem wykonać następujące czynności w nieokreślonej kolejności:

  • pg_resetxlog -D $PGDATA wykonał swoją pracę bez żadnych błędów i komunikatów
  • Usunięto wszystkie indeksy, w tym ograniczenia klucza

  • CREATE TABLE aaa AS (SELECT * FROM comments);prowadzi się Segmentation faultna

    heap_deform_tuple (tuple=tuple@entry=0x7f0d1be29b08, tupleDesc=tupleDesc@entry=0x7f0d1a35abe0, values=values@entry=0x7ffd57a5beb0, isnull=isnull@entry=0x7ffd57a65af0 "\001\001") Jest odtwarzalny i pozostawia zrzut pamięci około 9 GB.

  • SELECT COUNT(*) from comments;wolno VACUUM comments;wykonać, ta sama sztuczka nie działa na innych stołach.
  • SELECT COUNT(*) from photos;a VACUUM photos;teraz umiera ERROR: MultiXactId 302740528 has not been created yet -- apparent wraparound- ten nawiedza każdy stół, na którym nie pojawiają się inne błędy.

Myśli

  • DB był wbijany przez wiele ( prawdopodobnie zduplikowanych ) zapisów z ON CONFLICTklauzulą DB robił, VACUUMkiedy wystąpiła panika jądra, wierzę, że to, co z niego zostało, powoduje problemy nonexistent MultiXactIdsiinvisible tuple
  • Dane były gromadzone za pomocą robota przez ponad 2 lata i nie mam nic przeciwko utracie części z nich
  • Teraz robię kopie zapasowe
  • Nie było żadnych ograniczeń relacyjnych między tabelami ani żadnych wyzwalaczy

Oto dane wyjściowe pg_controldata:

pg_control version number:            942
Catalog version number:               201510051
Database system identifier:           6330224129664261958
Database cluster state:               in production
pg_control last modified:             Thu 08 Dec 2016 01:06:22 AM EET
Latest checkpoint location:           1562/8F9F8A8
Prior checkpoint location:            1562/8F7F460
Latest checkpoint's REDO location:    1562/8F9F8A8
Latest checkpoint's REDO WAL file:    000000010000156200000008
Latest checkpoint's TimeLineID:       1
Latest checkpoint's PrevTimeLineID:   1
Latest checkpoint's full_page_writes: on
Latest checkpoint's NextXID:          0/40781255
Latest checkpoint's NextOID:          67798231
Latest checkpoint's NextMultiXactId:  1
Latest checkpoint's NextMultiOffset:  0
Latest checkpoint's oldestXID:        615
Latest checkpoint's oldestXID's DB:   1
Latest checkpoint's oldestActiveXID:  0
Latest checkpoint's oldestMultiXid:   1
Latest checkpoint's oldestMulti's DB: 1
Latest checkpoint's oldestCommitTsXid:0
Latest checkpoint's newestCommitTsXid:0
Time of latest checkpoint:            Thu 08 Dec 2016 01:06:22 AM EET
Fake LSN counter for unlogged rels:   0/1
Minimum recovery ending location:     0/0
Min recovery ending loc's timeline:   0
Backup start location:                0/0
Backup end location:                  0/0
End-of-backup record required:        no
wal_level setting:                    minimal
wal_log_hints setting:                off
max_connections setting:              100
max_worker_processes setting:         8
max_prepared_xacts setting:           0
max_locks_per_xact setting:           64
track_commit_timestamp setting:       off
Maximum data alignment:               8
Database block size:                  8192
Blocks per segment of large relation: 131072
WAL block size:                       8192
Bytes per WAL segment:                16777216
Maximum length of identifiers:        64
Maximum columns in an index:          32
Maximum size of a TOAST chunk:        1996
Size of a large-object chunk:         2048
Date/time type storage:               64-bit integers
Float4 argument passing:              by value
Float8 argument passing:              by value
Data page checksum version:           0

Aktualizacje

  • ( 9 grudnia 2016 r. ) Czytając o nieistniejącym MultiXactIds , przypomniałem sobie, że moja baza danych nie była obciążona operacyjnie w chwili awarii, ale przetwarzała ręczne VACUUMżądanie. Przeniosłem serwery i roboty indeksujące do trybu offline, gdy zdałem sobie sprawę, że na dyskach pozostało tylko 3% miejsca. Powinienem był sprawdzić, czy nie ma /var/logdużych plików, ale przez pomyłkę obwiniłem PostgreSQL i próbowałem VACUUM FULL, ale okazało się, że został przerwany z powodu małej ilości miejsca na urządzeniu. Więc zacząłem zwykłe VACUUM i zostawiłem to przy tym.
  • ( 14 grudnia 2016 r. ) Pobrałem 9,5 gałąź źródeł PostgreSQL z Github, skomentowałem bloki w heapam.c i multixact.c i skompilowałem go z nadzieją, że nie wyrzuci tych błędów. Ale serwer nie chce się uruchomić, ponieważ musiał być skonfigurowany z tymi samymi flagami, co te, które miałem z APT. Było około 47 flag, z których każda wymagała zależności o nieoczywistej nazwie, więc zrezygnowałem z tego pomysłu.

  • ( 16 grudnia 2016 r. ) Znalazłem sposób na pozbycie się krotek z nieprawidłowymi znacznikami czasu poprzez wyzerowanie odpowiednich stron. Najpierw ustawiłem następujące opcje w psql:

    \set FETCH_COUNT 1
\pset pager off

    To robię SELECT ctid, * FROM comments;. W ten sposób wypluwa ctidzłą krotkę przed zakończeniem zapytania. Następnie przechodzę do wypełniania tej strony zerami: dd if=/dev/zero of=/var/lib/postgresql/9.5/main/base/16385/16443 bs=8K seek=92803 count=1 conv=notruncAle każda strona, wyzerowana w ten sposób, łamie poprzednią stronę, w wyniku czego strona 16442ma krotkę z niepoprawnym znacznikiem czasu. Nie jestem pewien, co robię źle tutaj.

  • ( 16 grudnia 2016 r. ) Próba pg_dump -Fc --table photos vw > photos.bakpowoduje błąd segmentacji po napisaniu 1,3 GB ( z prawdopodobnie 800 GB ). Oto dziennik serwera:

    2016-12-16 18:48:05 EET [19337-2] LOG:  server process (PID 29088) was terminated by signal 11: Segmentation fault
2016-12-16 18:48:05 EET [19337-3] DETAIL:  Failed process was running: COPY public.photos (id, owner_id, width, height, text, date, link, thumb, album_id, time_found, user_id, lat, long) TO stdout;
2016-12-16 18:48:05 EET [19337-4] LOG:  terminating any other active server processes
2016-12-16 18:48:05 EET [19342-2] WARNING:  terminating connection because of crash of another server process
2016-12-16 18:48:05 EET [19342-3] DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
2016-12-16 18:48:05 EET [19342-4] HINT:  In a moment you should be able to reconnect to the database and repeat your command.
2016-12-16 18:48:05 EET [19337-5] LOG:  all server processes terminated; reinitializing
2016-12-16 18:48:06 EET [29135-1] LOG:  database system was interrupted; last known up at 2016-12-14 22:58:59 EET
2016-12-16 18:48:07 EET [29135-2] LOG:  database system was not properly shut down; automatic recovery in progress
2016-12-16 18:48:07 EET [29135-3] LOG:  invalid record length at 1562/A302F878
2016-12-16 18:48:07 EET [29135-4] LOG:  redo is not required
2016-12-16 18:48:07 EET [29135-5] LOG:  MultiXact member wraparound protections are now enabled
2016-12-16 18:48:07 EET [19337-6] LOG:  database system is ready to accept connections
2016-12-16 18:48:07 EET [29139-1] LOG:  autovacuum launcher started

    Oto krótki ślad stosu:

    #0  pglz_decompress (source=source@entry=0x7fbfb6b99b13 "32;00/0ag4d/Jnz\027QI\003Jh3A.jpg", slen=<optimized out>,
    dest=dest@entry=0x7fbf74a0b044 "", rawsize=926905132)
#1  0x00007fc1bf120c12 in toast_decompress_datum (attr=0x7fbfb6b99b0b)
#2  0x00007fc1bf423c83 in text_to_cstring (t=0x7fbfb6b99b0b)

    Nie mam pojęcia, jak to obejść.

  • ( 29 grudnia 2016 r. ) Napisałem narzędzie, które robi to SELECT * FROM tablename LIMIT 10000 OFFSET 0, zwiększając przesunięcie i zawężając wokół martwych krotek i pomyślnie powielając dane na mojej lokalnej maszynie, z wyjątkiem krotek ( mam nadzieję, że jedyne ) ręcznie uszkodziłem. Ma także poczekać, aż serwer uruchomi się ponownie. Jednak na macierzy RAID nie miałem wystarczającej ilości miejsca i utworzyłem przestrzeń tabel slowdiskna dysku twardym o pojemności 8 TB. Kiedy próbuję CREATE DATABASE vwslow WITH TABLESPACE slowdisk, nie robi to z błędami:

    2016-12-29 02:34:13 EET [29983-1] LOG:  request to flush past end of generated WAL; request 950412DE/114D59, currpos 1562/A3030C70
2016-12-29 02:34:13 EET [29983-2] CONTEXT:  writing block 58368001 of relation base/16385/16473
2016-12-29 02:34:13 EET [29983-3] ERROR:  xlog flush request 950412DE/114D59 is not satisfied --- flushed only to 1562/A3030C70
2016-12-29 02:34:13 EET [29983-4] CONTEXT:  writing block 58368001 of relation base/16385/16473
2016-12-29 02:34:13 EET [30005-44212] postgres@vw ERROR:  checkpoint request failed
2016-12-29 02:34:13 EET [30005-44213] postgres@vw HINT:  Consult recent messages in the server log for details.
2016-12-29 02:34:13 EET [30005-44214] postgres@vw STATEMENT:  CREATE DATABASE vwslow WITH TABLESPACE slowdisk;

    Ręczne CHECKPOINTspowodowało te same błędy.

    Ponowne uruchomienie serwera sprawiło, że błąd punktu kontrolnego zniknął i pozwolił mi uruchomić moje narzędzie. Odpowie na moje pytanie i opublikuje kod, jeśli zadziała.

postgresql recovery corruption postgresql-9.5 disaster-recovery Kai
źródło
Przeczytaj to i działaj, zanim spróbujesz zrobić cokolwiek innego: wiki.postgresql.org/wiki/Corruption . Choć wygląda na to, że jest już trochę za późno. Podejrzewam, że główną przyczyną są problemy z dyskami / odbudową RAID.
Craig Ringer,
Czy zachowałeś kopię katalogu danych sprzed resetowania dziennika itp?
Craig Ringer
Nie sam datadir, ale przeniosłem surowe obrazy dysków poza miejsce, gdzie są bezpieczniejsze. Są w porządku, ponieważ odbudowałem z nich moją macierz RAID.
Kai
1
@CraigRinger napiszesz na ten temat odpowiedź? Prawdopodobnie jesteś jednym z niewielu użytkowników, którzy odpowiadają w tagu Postgres i mogą powiedzieć coś przydatnego na ten temat. Wydaje się, że niewiele można zrobić.
ypercubeᵀᴹ
4
Nie znajdziesz odpowiedzi na to pytanie. Erwin może ci pomóc. Nieśmiałe, poszukaj Davida Fettera lub AndrewSW / RhodiumToad na irc.freenode.net/#postgresql. Powiedz nam (dba.se), co znajdą. Mam wrażenie, że będzie to płatna praca doradcza, która będzie wymagała pełnego dostępu do twojej bazy danych. developer.postgresql.org/~adunstan linkedin.com/in/davidfetter Nie mam powiązań z żadnym z tych facetów ani z ich firmami. Ale są to jedyne osoby, którym osobiście ufałbym, aby wydostać się z tego problemu.
Evan Carroll

Odpowiedzi:

2

Udało mi się zautomatyzować proces odzyskiwania SELECTi INSERT INTOpomijanie zakresów i oczekiwanie na awarię serwera. Najpierw zakodowałem go w węźle - zgrał nieuszkodzone dane commentsi nadal trwa.

Wczoraj zdecydowałem się wypróbować Golang, a oto repozytorium z kodem Go: https://github.com/kaivi/pg_ripper Niedługo go zaktualizuję, aby naprawdę działał wokół złych krotek, a nie po prostu rezygnuje z całości zakres zawierający jeden.

Kai
źródło