[ABANDONNE] [9.6] Plus de checkpoint

jeff7194 · 09/12/2019 23:52:42

Bonjour,

J'ai une base qui tourne sous PostgreSQL 9.6 / Ubuntu 12.04 (volumétrie ~ 80Go)

Voilà quelques jours, le filesystem a été saturé par l'archivage des fichiers WAL... je sais c'est ballot mais c'est conçu ainsi.
De la place a pu être libérée et la base a repris son fonctionnement sans qu'aucune relance de service n'ait été nécessaire.

Toutefois, j'ai depuis constaté que le dossier pg_xlog ne se vidait plus.
Plus de sauvegarde non plus (basée sur amanda), le pg_start_backup() n'aboutit jamais.

En fait, il n'y a plus aucun checkpoint qui passe sur la base et un pg_controldata indique que le dernier date du moment de la saturation disque.
Lancée manuellement, la commande CHECKPOINT ne rend jamais la main même après plusieurs heures.

N'ayant pas trouvé secours auprès de mes DBA j'espère que la communauté pourra m'aider.
La base étant répliquée, la solution ultime restera la bascule et la reconstruction du moteur master par pg_basebackup/pg_rewind

Salutations.
JF

Dernière modification par jeff7194 (03/01/2020 01:14:59)

rjuju · 10/12/2019 07:14:59

Comment avez-vous libéré de l'espace ? Y a-t-il des messages d'erreurs pertinents dans les logs ? Quel est l'état du processus checkpointeur côté système (utilisation CPU,voire un strace rapide histoire de vérifier ce qu'il fait dans un premier temps).

jeff7194 · 11/12/2019 11:23:20

Pour info complémentaire, ce que retourne un strace du process checkpointer lors d'un CHECKPOINT :

semop(3014694, {{4, -1, 0}}, 1
 
 
)         = -1 EINTR (Interrupted system call)
--- SIGINT (Interrupt) @ 0 (0) ---
rt_sigreturn(0x7fb272979904)            = -1 EINTR (Interrupted system call)

Pa d'erreur notable dans pg_log, seulement lors de l'interruption de la commande :

2019-12-11 08:54:35 GMT postgres@[local] (postgres) [8419]  ERROR:  canceling statement due to user request
2019-12-11 08:54:35 GMT postgres@[local] (postgres) [8419]  STATEMENT:  CHECKPOINT;

Pour le process checkpointer, pas de consommation CPU/RAM particulière, tout à fait similaire à un autre environnement :

PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
 9471 postgres  20   0 6435m 6.1g 6.1g S    0  9.7 519:31.75 postgres

Ça correspond donc à un PGSemaphoreLock(). J'imagine qu'il s'agit de celui correspondant à l'attente durant LWLockAcquire(). Malheureusement, je pense que la seule manière d'en savoir plus sur la cause de ce verrou non accordé (ou autre cause d'attente sur sémaphore) est d'inspecter le processus avec gdb et d'afficher sa stack trace, en ayant pris soin d'installer les symboles de debug. Vous pouvez consulter https://wiki.postgresql.org/wiki/Gettin … _Linux/BSD en cas de besoin.

jeff7194 · 11/12/2019 11:58:10

Un strace d'un checkpoint sur un moteur fonctionnel

epoll_wait(6,

7f99e19a1160, 1, 37688)   = -1 EINTR (Interrupted system call)
--- SIGINT (Interrupt) @ 0 (0) ---
write(12, "\0", 1)                      = 1
rt_sigreturn(0xc)                       = -1 EINTR (Interrupted system call)
close(6)                                = 0
write(2, "2019-12-11 09:34:07 GMT @ () [58"..., 85) = 85
open("pg_replslot/base_backup_slot/state.tmp", O_WRONLY|O_CREAT|O_EXCL, 0600) = 6
write(6, "\241\34\5\1G\315\361\r\2\0\0\0\240\0\0\0base_backup_slot"..., 176) = 176
fsync(6)                                = 0
close(6)                                = 0
rename("pg_replslot/base_backup_slot/state.tmp", "pg_replslot/base_backup_slot/state") = 0
open("pg_replslot/base_backup_slot/state", O_RDWR) = 6
fsync(6)                                = 0
close(6)                                = 0
open("pg_replslot/base_backup_slot", O_RDONLY) = 6
fsync(6)                                = 0
close(6)                                = 0
open("pg_replslot", O_RDONLY)           = 6
fsync(6)                                = 0
close(6)                                = 0
openat(AT_FDCWD, "pg_logical/snapshots", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 6
getdents(6, /* 2 entries */, 32768)     = 48
getdents(6, /* 0 entries */, 32768)     = 0
close(6)                                = 0
openat(AT_FDCWD, "pg_logical/mappings", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 6
getdents(6, /* 2 entries */, 32768)     = 48
getdents(6, /* 0 entries */, 32768)     = 0
close(6)                                = 0
unlink("pg_logical/replorigin_checkpoint.tmp") = -1 ENOENT (No such file or directory)
open("pg_logical/replorigin_checkpoint.tmp", O_WRONLY|O_CREAT|O_EXCL, 0600) = 6
write(6, "\336\332W\22", 4)             = 4
write(6, "6\262\0j", 4)                 = 4
close(6)                                = 0
open("pg_logical/replorigin_checkpoint.tmp", O_RDWR) = 6
fsync(6)                                = 0
close(6)                                = 0
open("pg_logical/replorigin_checkpoint", O_RDWR) = 6
fsync(6)                                = 0
close(6)                                = 0
rename("pg_logical/replorigin_checkpoint.tmp", "pg_logical/replorigin_checkpoint") = 0
open("pg_logical/replorigin_checkpoint", O_RDWR) = 6
fsync(6)                                = 0
close(6)                                = 0
open("pg_logical", O_RDONLY)            = 6
...

jeff7194 · 11/12/2019 13:00:34

Pour la libération d'espace, par chance un gros fichier trainait sur le FS... qui n'avait rien à y faire.
Aucun fichier lié au moteur n'a été supprimé.

rjuju · 11/12/2019 16:23:46

Pour info complémentaire, ce que retourne un strace du process checkpointer lors d'un CHECKPOINT :

semop(3014694, {{4, -1, 0}}, 1
 
 
)         = -1 EINTR (Interrupted system call)
--- SIGINT (Interrupt) @ 0 (0) ---
rt_sigreturn(0x7fb272979904)            = -1 EINTR (Interrupted system call)

Pa d'erreur notable dans pg_log, seulement lors de l'interruption de la commande :

2019-12-11 08:54:35 GMT postgres@[local] (postgres) [8419]  ERROR:  canceling statement due to user request
2019-12-11 08:54:35 GMT postgres@[local] (postgres) [8419]  STATEMENT:  CHECKPOINT;

Pour le process checkpointer, pas de consommation CPU/RAM particulière, tout à fait similaire à un autre environnement :

PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
 9471 postgres  20   0 6435m 6.1g 6.1g S    0  9.7 519:31.75 postgres

Ça correspond donc à un PGSemaphoreLock(). J'imagine qu'il s'agit de celui correspondant à l'attente durant LWLockAcquire(). Malheureusement, je pense que la seule manière d'en savoir plus sur la cause de ce verrou non accordé (ou autre cause d'attente sur sémaphore) est d'inspecter le processus avec gdb et d'afficher sa stack trace, en ayant pris soin d'installer les symboles de debug. Vous pouvez consulter https://wiki.postgresql.org/wiki/Gettin … _Linux/BSD en cas de besoin.

jeff7194 · 13/12/2019 00:03:39

Pas eu le temps d'analyser plus avant le problème aujourd'hui.
Toutefois, une sauvegarde de la base selon son mode habituel, en shuntant le pg_start_backup, a pu être rechargée sur un serveur de test.
Avec la mise en ligne des quelque 30Go de fichiers WAL générés depuis le dernier checkpoint valide, la base a démarré sans anomalie et les checkpoints passent normalement, y compris la sauvegarde.

Sur cette environnement de test, petite expérience qui ne coûtait rien, un "kill -9" du process checkpointer.
Le moteur n'a pas planté, juste une refresh de l'ensemble de tous les process fils de PostgresSQL (writer, vaccum, etc)

A dire que c'est ce quipourrait être joué sur l'environnement principal...

Test de saturation du FS à venir en espérant reproduite le même phénomène.

rjuju · 13/12/2019 13:40:23

jeff7194 a écrit :

Toutefois, une sauvegarde de la base selon son mode habituel, en shuntant le pg_start_backup, a pu être rechargée sur un serveur de test.

Le résultat de cette sauvegarde est très probablement une instance totalement corrompue.

jeff7194 · 14/12/2019 12:46:51

Je ne suis pas certain quant à la corruption puisque ce qui a été restauré selon procédure correspond à ce qui aurait été embarqué dans une sauvegarde qui n'aurait pas tourné depuis plusieurs jours.

Dilemme avec la saturation du FS sur l'environnement de test où le contexte n'est pas reproduit... le moteur a fait un shutdown brutal... contrairement à l'environnement principal qui lui tourne toujours.

rjuju · 14/12/2019 16:10:50

jeff7194 a écrit :

Je ne suis pas certain quant à la corruption puisque ce qui a été restauré selon procédure correspond à ce qui aurait été embarqué dans une sauvegarde qui n'aurait pas tourné depuis plusieurs jours.

Oui, mais les WAL nécessaires pour obtenir des données cohérentes n'ont probablement pas été rejoués. C'est entre autre à ça que sert le pg_start_backup().

gleu · 14/12/2019 16:19:59

Sans faire appel à pg_start_backup(), le moteur ne saura pas à quel checkpoint commencer la restauration. Il se basera sur le contenu du fichier pg_control. Si ce dernier n'a pas été modifié depuis le début de la sauvegarde, parfait. S'il l'a été, votre sauvegarde est corrompue. Si on cherche à estimer ça, prenez la valeur du checkpoint_timeout. Si la durée de la sauvegarde dépasse la valeur du checkpoint_timeout, alors la sauvegarde est corrompue.

rjuju · 14/12/2019 22:03:18

Je tiens quand même à préciser que même si la sauvegarde ne dure qu'une milliseconde, il est tout de même possible de finir avec une sauvegarde corrompue pour peu que le fichier pg_control corresponde à une version plus récente que certains autre fichiers modifiés.

gleu · 15/12/2019 18:57:40

Oui, tout à fait. Je cherchais juste à indiquer à quel moment au plus tard on était assuré d'avoir une sauvegarde corrompue.

jeff7194 · 17/12/2019 01:17:50

Le fichier pg_control reste bien en date du dernier CHECKPOINT.
Mon sentiment est donc que ce qui a été restauré sur l'environnement de test est basé sur à une sauvegarde qui n'aurait pas été lancée depuis ce CHECKPOINT... à noter qu'en temps normal la sauvegarde est loi d'être instantanée, mais autour de 30min.
Toutefois, je précise que l'objectif n'est pas de faire une restauration sur l'environnement principal, il s'agissait de vérifier en test que les fichiers sur disque n'étaient pas corrompus.

Ce dont je reste preneur, ce serait une solution indolore pour "réveiller" le process checkpointer.

rjuju · 17/12/2019 12:53:58

Ce dont je reste preneur, ce serait une solution indolore pour "réveiller" le process checkpointer.

Malheureusement, comme c'est la première fois que j'entends parler de ce problème, sans plus d'informations (au minimum la stack trace du processus), il va être impossible d'aider.

jeff7194 · 23/12/2019 17:08:01

La stack est très parlante...

# pstack 9471

9471: postgres: checkpointer process
(No symbols found)
0x7fb2781583e7: ???? (1007ffdeb7b9270, 7fb2729798f8, 0, 7fb2739c4400, 7ffdeb7b9420, 7ffdeb7b9520) + 10
0x7fb27a0c4f0c: ???? (7ffdeb7b9398, f7a334613, 7ffdeb7b9290, 7ffdeb7b9280, 7ffdeb7b9468, 7fb27a2349cd) + 8d0
0x7fb27a097c47: ???? (736c7065725f6770, 657361622f746f6c, 5f70756b6361625f, 34353a00746f6c73, 7ffdeb7b9620, 7fb2781a4b60) + 410
0x7fb27a099657: ???? (7fb27a61f1b8, 7fb27a637d58)
0x7fb279eb818a: ???? (3, cfe52b00, 1192c7000060, 200000002, 1, 1162b5906845a2f) + 70
0x7fb279ec00c0: ???? (7ffdeb7b9a70, 7fb27bdd0290, 7fb27a60f680, 8d01f7267e7cf438, 2, 7fb27a22b520) + e0
0x7fb27a065ae9: ???? (4, 0, 0, 7fb27a1f8d9c, 7ffdeb7b9bb0, 7fb27a638550) + 20
0x7fb279ed15c9: ???? (7fb27a318cd0, 7ffdeb7b9c10, 0, 5, 7ffdeb7b9b40, 10) + 60
0x7fb27a06ee27: ???? (7ffdeb7b9c90, 7fb2781646b9, 0, 7841a720, 7ffdeb7b9f20, 0) + 20
0x7fb27a07001a: ???? (1, 0, 0, 7fb200000002, 0, 7ffdeb7ba3c0) + 730
0x7fb2780960b0: ???? (7ffdeb7ba578, 0, 7fb279e48114, 7ffdeb7ba540, 0, 0)
0x7fb279e480e2: ???? (7ffdeb7ba578, 7ffdeb7ba548, 500000000, 7fb279e478c0, 0, 72fa21d148dcf438) + ffff800214845b60

jeff7194 · 23/12/2019 17:24:58

(gdb) backtrace
#0  0x00007fb2781583e7 in semop () from /lib/x86_64-linux-gnu/libc.so.6
#1  0x00007fb27a05f202 in PGSemaphoreLock ()
#2  0x00007fb27a0c4f0c in LWLockAcquire ()
#3  0x00007fb27a097c47 in ?? ()
#4  0x00007fb27a099657 in CheckPointReplicationSlots ()
#5  0x00007fb279eb818a in ?? ()
#6  0x00007fb279ec00c0 in CreateCheckPoint ()
#7  0x00007fb27a065ae9 in CheckpointerMain ()
#8  0x00007fb279ed15c9 in AuxiliaryProcessMain ()
#9  0x00007fb27a06ee27 in ?? ()
#10 0x00007fb27a07001a in ?? ()
#11 <signal handler called>
#12 0x00007fb27814f613 in select () from /lib/x86_64-linux-gnu/libc.so.6
#13 0x00007fb27a07149a in PostmasterMain ()
#14 0x00007fb279e480e2 in main ()

rjuju · 24/12/2019 11:45:49

Donc, le checkpoint est bloqué sur la partie des slots de réplication, en attente du lightweight lock ReplicationSlotAllocationLock en accès partagé. Les seuls endroits dans le code où ce verrou est pris de manière exclusive est dans ReplicationSlotCreate(), c'est-à-dire lorsqu'un slot de réplication est créé et ReplicationSlotDropPtr(), pour supprimer un slot. Je ne vois à priori aucune possibilité de deadlock ou de non relachement de ce verrou dans le code. Quelle version mineure de postgres utilisez-vous exactement ?

Avez-vous eu un problème durant la création de slot de réplication ? Avez-vous une requête bloquée depuis (très) longtemps exécutant pg_create_(physical|logical)_replication_slot(), pg_drop_replication_slot(), ou une autre requête qui semble bloquée? Il faudrait trouver quel processus détient ce verrou, mais malheureusement l'information n'est pas facilement disponible avec un build standard de postgres.

En tout logique, vous ne devriez pas non plus pouvoir créer ou supprimer de slot de réplication.

jeff7194 · 25/12/2019 01:33:43

Je suis dépité... horreur en me connectant ce mardi matin pour faire l'état des lieux...

Bien que ce soit certainement sans mauvaises intentions, je n'ai pas pu faire avouer, je pense qu'un lutin venait à l'instant de me planter le moteur en tuant le process checkpointer !
Le process père a résisté et, comme sur l'environnement de test, tous les process fils ont été recyclés..

Magie de l'ambiance de Noël, checkpoint et sauvegardes refonctionnent
Le dossier pg_xlog a repris un cycle de vie et de purge normal.

Je n'ai eu aucun écho d'un dysfonctionnement de l'application ou même d'incohérences de données.
J'ai contrôlé la réplication et elle était toujours fonctionnelles.
Je reste dubitatif sur l'état réel du moteur et je pense qu'une reconstruction à court terme est à envisager.

Je rechercherai s'il s'agit bien d'une action humaine ou finalement d'une véritable défaillance du moteur telle qu'elle aurait pu/dû de produire initialement.

rjuju · 25/12/2019 20:13:40

Ça ne me parait pas spécialement surprenant que le checkpointer finisse par exploser en vol, il serait cependant intéressant de savoir ce qui l'a vraiment tué.

Pour le reste, à priori je ne vois pas de raison qui ferait que des données seraient corrompues : tous les WALs étaient présentes, les fichiers ont été à priori normalement écrits etc etc. Vous pouvez essayer d'utiliser des outils comme amcheck ou pg_catcheck au cas où, mais cela ne garantirait que peu de choses.

jeff7194 · 03/01/2020 01:13:34

Après quelques jours de congés, première chose regardé à ma reprise et j'ai la réponse... action humaine "in"volontaire avec un beau kill du process retrouvé dans l'historique des commandes.
Depuis, le moteur ne semble pas avoir bronché.

Merci pour vos contributions bien qu'elles n'aient pas eu le temps de conduire à une résolution non violente.

#1 09/12/2019 23:52:42

[ABANDONNE] [9.6] Plus de checkpoint

#2 10/12/2019 07:14:59

Re : [ABANDONNE] [9.6] Plus de checkpoint

#3 11/12/2019 11:23:20

Re : [ABANDONNE] [9.6] Plus de checkpoint

#4 11/12/2019 11:58:10

Re : [ABANDONNE] [9.6] Plus de checkpoint

#5 11/12/2019 13:00:34

Re : [ABANDONNE] [9.6] Plus de checkpoint

#6 11/12/2019 16:23:46

Re : [ABANDONNE] [9.6] Plus de checkpoint

#7 13/12/2019 00:03:39

Re : [ABANDONNE] [9.6] Plus de checkpoint

#8 13/12/2019 13:40:23

Re : [ABANDONNE] [9.6] Plus de checkpoint

#9 14/12/2019 12:46:51

Re : [ABANDONNE] [9.6] Plus de checkpoint

#10 14/12/2019 16:10:50

Re : [ABANDONNE] [9.6] Plus de checkpoint

#11 14/12/2019 16:19:59

Re : [ABANDONNE] [9.6] Plus de checkpoint

#12 14/12/2019 22:03:18

Re : [ABANDONNE] [9.6] Plus de checkpoint

#13 15/12/2019 18:57:40

Re : [ABANDONNE] [9.6] Plus de checkpoint

#14 17/12/2019 01:17:50

Re : [ABANDONNE] [9.6] Plus de checkpoint

#15 17/12/2019 12:53:58

Re : [ABANDONNE] [9.6] Plus de checkpoint

#16 23/12/2019 17:08:01

Re : [ABANDONNE] [9.6] Plus de checkpoint

#17 23/12/2019 17:24:58

Re : [ABANDONNE] [9.6] Plus de checkpoint

#18 24/12/2019 11:45:49

Re : [ABANDONNE] [9.6] Plus de checkpoint

#19 25/12/2019 01:33:43

Re : [ABANDONNE] [9.6] Plus de checkpoint

#20 25/12/2019 20:13:40

Re : [ABANDONNE] [9.6] Plus de checkpoint

#21 03/01/2020 01:13:34

Re : [ABANDONNE] [9.6] Plus de checkpoint

Pied de page des forums

À propos

Nous contacter

Groupes Locaux

Réseaux Sociaux