PostgreSQL DELETE FROM falla con `Error: intentó eliminar la tupla invisible`

25

El error

Intentando eliminar tuplas que contienen marcas de tiempo inválidas con

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 en

ERROR:  attempted to delete invisible tuple

Hay una lista de correo de 2009 que discute exactamente el mismo mensaje de error, donde OP lo solucionó, pero no encuentro ninguna explicación de cómo lo hizo o qué podría haber llevado a este error.

Estoy indefenso debido a la falta de visitas a Google y a mi limitado conocimiento de PostgreSQL.

¿Qué llevó a la corrupción?

He tenido un servidor PostgreSQL 9.5.5 ( ~ 4 TB de datos, todas las configuraciones predeterminadas, excepto los límites de memoria aumentados ) ejecutándose en Debian 8, cuando el núcleo del sistema operativo entró en pánico, probablemente mientras se reconstruía / dev / md1 donde se encontraba el intercambio. Antes de eso, PostgreSQL ocupó casi todo el espacio en disco con un archivo de registro de 400 GB. El sistema operativo nunca se reinició de nuevo, las comprobaciones de disco estaban bien, así que arranqué desde un LiveCD y realicé una copia de seguridad de cada dispositivo de bloque en imágenes, por si acaso. Reconstruí con éxito el directorio / desde / dev / md2, fsck mostró un sistema de archivos limpio y hice una copia de seguridad de la carpeta PGDATA en un HDD externo.

Lo que hice para intentar recuperarme

Después de formatear los dispositivos md y reinstalar el sistema operativo junto con un nuevo postgresql-9.5, detuve el servidor PostgreSQL, moví y puse la carpeta PGDATA al usuario de postgres, e inicié el servidor; todo parecía estar bien, no hubo errores.

Tan pronto como comencé pg_dumpall, murió con

Error message from server: ERROR:  timestamp out of range

Naturalmente, he intentado eliminar las tuplas ofensivas, solo para terminar con el mismo invisible tupleerror una y otra vez.

Cosas que probé

En primer lugar, las consultas DELETE fallaron debido a páginas dañadas, así que configuré las siguientes configuraciones:

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

Ahora he notado que cuando vuelvo a ejecutar las mismas consultas, el servidor pone a cero las mismas páginas una y otra vez, sin estar seguro de lo que significa:

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

He intentado seguir en un orden indefinido:

  • pg_resetxlog -D $PGDATA hizo su trabajo sin ningún error o mensaje
  • Se eliminaron todos los índices, incluidas las restricciones de pkey

  • CREATE TABLE aaa AS (SELECT * FROM comments);conduce a Segmentation faulten

    heap_deform_tuple (tuple=tuple@entry=0x7f0d1be29b08, tupleDesc=tupleDesc@entry=0x7f0d1a35abe0, values=values@entry=0x7ffd57a5beb0, isnull=isnull@entry=0x7ffd57a65af0 "\001\001") Es reproducible y deja un volcado de núcleo de ~ 9 GB.

  • SELECT COUNT(*) from comments;permitido VACUUM comments;completar, el mismo truco no funciona en otras tablas.
  • SELECT COUNT(*) from photos;y VACUUM photos;ahora muere con ERROR: MultiXactId 302740528 has not been created yet -- apparent wraparound: este persigue todas las mesas, donde otros errores ya no aparecen.

Pensamientos

  • DB fue golpeado por muchas ( posiblemente duplicadas ) escrituras con la ON CONFLICTcláusula que DB estaba haciendo VACUUMcuando ocurrió el pánico del kernel, creo que es lo que queda de eso lo que está causando problemas nonexistent MultiXactIdsyinvisible tuple
  • Los datos se recopilaron con el rastreador durante un período de más de 2 años, y estoy totalmente de acuerdo con perder parte de ellos.
  • Ahora hago copias de seguridad
  • No hubo restricciones relacionales entre tablas ni desencadenantes

Aquí está la salida pg_controldata a partir de ahora:

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

Actualizaciones

  • ( 9 de diciembre de 2016 ) Mientras leía sobre MultiXactIds inexistentes , recordé que mi base de datos no estaba bajo carga operativa en el momento del bloqueo, pero estaba procesando una VACUUMsolicitud manual . He desconectado los servidores web y los rastreadores después de darme cuenta de que solo quedaba un 3% de espacio en los discos. Debería haber buscado /var/logarchivos grandes, pero culpé por error a PostgreSQL e intenté VACUUM FULL, solo para encontrarlo abortado debido a que queda poco espacio en el dispositivo. Así que comencé VACUUM ordinario y lo dejé así.
  • ( 14 de diciembre de 2016 ) Descargué una rama 9.5 de fuentes PostgreSQL de Github, comenté bloques en heapam.c y multixact.c y lo compilé con la esperanza de que no arroje estos errores. Pero el servidor no se iniciaba, porque tenía que configurarse con los mismos indicadores utilizados en uno que tenía de APT. Había alrededor de 47 banderas, cada una de las cuales requería una dependencia con un nombre no obvio, así que renuncié a esa idea.

  • ( 16 de diciembre de 2016 ) He encontrado una manera de deshacerme de las tuplas con marcas de tiempo inválidas al poner a cero las páginas relevantes. Primero configuro las siguientes opciones en psql:

    \set FETCH_COUNT 1
\pset pager off

    Entonces lo hago SELECT ctid, * FROM comments;. De esa manera, escupe ctiduna tupla incorrecta antes de que la consulta muera. Luego procedo a llenar esa página con ceros: dd if=/dev/zero of=/var/lib/postgresql/9.5/main/base/16385/16443 bs=8K seek=92803 count=1 conv=notruncpero cada página, puesta a cero de esta manera, rompe la página anterior, lo que hace que la página 16442ahora tenga una tupla con marca de tiempo no válida. No estoy seguro de lo que estoy haciendo mal aquí.

  • ( 16 de diciembre de 2016 ) Intento de pg_dump -Fc --table photos vw > photos.bakresultados en la falla de segmentación después de 1.3GB ( probablemente de 800GB ) escrito. Aquí está el registro del 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

    Aquí hay un pequeño 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)

    No tengo idea de cómo solucionarlo.

  • ( 29 de diciembre de 2016 ) He escrito una utilidad que lo hace SELECT * FROM tablename LIMIT 10000 OFFSET 0, incrementando el desplazamiento y reduciendo las tuplas muertas, y ha duplicado con éxito los datos en mi máquina local, excepto las tuplas ( espero que sean las únicas ) que he dañado manualmente. También se supone que debe esperar si el servidor se reinicia. Sin embargo, no tenía suficiente espacio en mi RAID, y he creado un espacio slowdiskde tabla en un disco duro de 8TB. Cuando lo intento CREATE DATABASE vwslow WITH TABLESPACE slowdisk, no lo hará con errores:

    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 CHECKPOINTresultó en los mismos errores.

    Un reinicio del servidor ha hecho que el error del punto de control desaparezca y me permite ejecutar mi herramienta. Contestaré mi pregunta y publicaré el código si funciona.

postgresql recovery corruption postgresql-9.5 disaster-recovery Kai
fuente
Lea esto y actúe en consecuencia antes de intentar hacer cualquier otra cosa: wiki.postgresql.org/wiki/Corruption . Aunque parece que es un poco tarde. Sospecho fuertemente que los problemas de disco / reconstrucción RAID son la causa principal aquí.
Craig Ringer
¿Guardaste una copia del directorio de datos de antes de hacer un resetxlog, etc.?
Craig Ringer
No es el datadir en sí, pero he movido imágenes de disco sin formato fuera del sitio donde son más seguras. Están bien, porque he reconstruido mi RAID de ellos.
Kai
1
@ CraigRinger, ¿escribirás una respuesta sobre esto? Probablemente sea uno de los pocos usuarios que responde en la etiqueta de Postgres y podría decir algo útil sobre el tema. Parece que se puede hacer muy poco.
ypercubeᵀᴹ
44
No vas a encontrar la respuesta en este caso. Erwin puede ayudarte. Tímido, busque David Fetter o AndrewSW / RhodiumToad en irc.freenode.net/#postgresql. Cuéntanos (dba.se) qué encuentran. Tengo la sensación de que este será un trabajo de consultoría remunerado que requerirá acceso total a su base de datos. developer.postgresql.org/~adunstan linkedin.com/in/davidfetter No tengo afiliación con ninguno de esos tipos ni con sus empresas. Pero, son los únicos en los que personalmente confiaría para salir de ese obstáculo.
Evan Carroll

Respuestas:

2

Bueno, he conseguido automatizar el proceso de recuperación de SELECTy INSERT INTO, pasando por alto las gamas y esperando si el servidor se bloquea. Primero lo codifiqué en Node: arrancó datos no dañados commentsy aún continúa.

Ayer decidí probar Golang, y aquí hay un repositorio con el código Go: https://github.com/kaivi/pg_ripper. Lo actualizaré pronto, así que realmente funciona con tuplas malas, y no solo se rinde en general. rango que contiene uno.

Kai
fuente