PostgreSQL DELETE FROM falha com `Erro: tentativa de excluir tupla invisível`

O erro

Tentando excluir tuplas contendo timestamps inválidos com

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';

termina em

ERROR:  attempted to delete invisible tuple

Há uma lista de discussão de 2009 discutindo exatamente a mesma mensagem de erro, onde o OP a corrigiu, mas não encontro nenhuma explicação de como ele fez isso ou o que pode ter levado a esse erro.

Estou desamparado devido à falta de acessos no Google e ao meu conhecimento limitado de PostgreSQL.

O que levou à corrupção

Eu tive um servidor PostgreSQL 9.5.5 ( ~ 4 TB de dados, todas as configurações padrão, exceto para limites de memória aumentados ) rodando no Debian 8, quando o kernel do sistema operacional entrou em pânico - provavelmente durante a reconstrução de /dev/md1 onde a troca estava localizada. Antes disso, o PostgreSQL ocupava quase todo o espaço em disco com um arquivo de log de 400 GB. O sistema operacional nunca inicializou novamente, as verificações de disco estavam OK, então inicializei a partir de um LiveCD e fiz backup de cada dispositivo de bloco em imagens, apenas por precaução. Eu reconstruí / diretório com sucesso de /dev/md2, fsck mostrou um sistema de arquivos limpo e fiz backup da pasta PGDATA em um HDD externo.

O que eu fiz para tentar a recuperação

Depois de formatar os dispositivos md e reinstalar o sistema operacional junto com um novo postgresql-9.5, parei o servidor PostgreSQL, movi e alterei a pasta PGDATA para o usuário postgres e iniciei o servidor - tudo parecia bem, não havia erros.

Assim que comecei pg_dumpall, morreu com

Error message from server: ERROR:  timestamp out of range

Eu naturalmente tentei excluir as tuplas ofensivas, apenas para acabar com o mesmo invisible tupleerro repetidamente.

Coisas que eu tentei

Em primeiro lugar, as consultas DELETE falharam devido a páginas danificadas, então defini as seguintes configurações:

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

Agora notei que, quando executo as mesmas consultas novamente, o servidor zera as mesmas páginas repetidamente, sem saber o que isso significa:

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

Eu tentei seguir em uma ordem indefinida:

• pg_resetxlog -D $PGDATAfez o seu trabalho sem erros ou mensagens
• Excluídos todos os índices, incluindo restrições de pkey

• CREATE TABLE aaa AS (SELECT * FROM comments);leva Segmentation faulta

  heap_deform_tuple (tuple=tuple@entry=0x7f0d1be29b08, tupleDesc=tupleDesc@entry=0x7f0d1a35abe0, values=values@entry=0x7ffd57a5beb0, isnull=isnull@entry=0x7ffd57a65af0 "\001\001") É reproduzível e deixa um despejo de núcleo de ~ 9 GB.

• SELECT COUNT(*) from comments;permissão VACUUM comments;para completar, o mesmo truque não funciona em outras mesas.
• SELECT COUNT(*) from photos;e VACUUM photos;agora morre com ERROR: MultiXactId 302740528 has not been created yet -- apparent wraparound– este assombra todas as mesas, onde outros erros não aparecem mais.

Pensamentos

• O banco de dados estava sendo martelado por muitas gravações ( possivelmente duplicadasON CONFLICT ) com a cláusula que o banco de dados estava fazendo VACUUMquando o pânico do kernel ocorreu, acredito que é o que resta dele que está causando problemas com nonexistent MultiXactIdseinvisible tuple
• Os dados foram coletados com o rastreador durante um período de mais de 2 anos e estou totalmente bem em perder alguns deles
• Agora eu faço backups
• Não havia restrições relacionais entre tabelas nem gatilhos

Aqui está a saída pg_controldata a partir de agora:

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

Atualizações

• ( 9 de dezembro de 2016 ) Ao ler sobre MultiXactIds inexistentes , lembrei-me de que meu banco de dados não estava sob carga operacional no momento da falha, mas estava processando uma VACUUMsolicitação manual. Coloquei os servidores da Web e rastreadores offline depois que percebi que havia apenas 3% de espaço restante nos discos. Eu deveria ter verificado /var/logarquivos grandes, mas culpei erroneamente o PostgreSQL e tentei VACUUM FULL, apenas para descobrir que ele foi abortado devido ao pouco espaço restante no dispositivo. Então eu comecei o VACUUM comum e deixei por isso mesmo.
• ( 14 de dezembro de 2016 ) Baixei uma ramificação 9.5 de fontes do PostgreSQL do Github, comentei blocos em heapam.c e multixact.c e o compilei com a esperança de que não lançaria esses erros. Mas o servidor não iniciava, pois tinha que ser configurado com os mesmos flags que usei em um que eu tinha do APT. Havia cerca de 47 sinalizadores, cada um exigindo uma dependência com nome não óbvio, então desisti dessa ideia.

• ( 16 de dezembro de 2016 ) Encontrei uma maneira de me livrar de tuplas com carimbos de data/hora inválidos, zerando as páginas relevantes. Primeiro defino as seguintes opções em psql:

  \set FETCH_COUNT 1
  \pset pager off
  

  Eu então faço SELECT ctid, * FROM comments;. Dessa forma, ele descarta ctiduma tupla incorreta antes que a consulta morra. Em seguida, preencho essa página com zeros: dd if=/dev/zero of=/var/lib/postgresql/9.5/main/base/16385/16443 bs=8K seek=92803 count=1 conv=notruncMas cada página, zerada dessa maneira, quebra a página anterior, resultando em uma página 16442com uma tupla com registro de data e hora inválido. Não tenho certeza do que estou fazendo de errado aqui.

• ( 16 de dezembro de 2016 ) A tentativa pg_dump -Fc --table photos vw > photos.bakresulta em falha de segmentação após a gravação de 1,3 GB ( provavelmente de 800 GB ). Aqui está o log do servidor:

  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
  

  Aqui está um pequeno stacktrace:

  #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)
  

  Não tenho ideia de como contornar isso.

• ( 29 de dezembro de 2016 ) Eu escrevi um utilitário que faz SELECT * FROM tablename LIMIT 10000 OFFSET 0, incrementando o deslocamento e reduzindo em torno de tuplas mortas, e ele duplicou com sucesso os dados em minha máquina local, exceto as tuplas ( espero que sejam as únicas ) que eu corromperi manualmente. Também deve esperar se o servidor for reiniciado. No entanto, não havia espaço suficiente no meu RAID e criei um tablespace slowdiskem um HDD de 8 TB. Quando tento CREATE DATABASE vwslow WITH TABLESPACE slowdisk, não o faço com erros:

  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;
  

  Manual CHECKPOINTresultou nos mesmos erros.

  Uma reinicialização do servidor fez com que o erro do ponto de verificação desaparecesse e deixe-me executar minha ferramenta. Responderá à minha pergunta e publicará o código se funcionar.