Vous n'êtes pas identifié(e).
Bonjour,
lors d'une restauration du type PITR, avec un volume assez important de fichiers WAL d'archive à restaurer, le système de fichiers des fichiers WAL actifs (pg_xlog) a été saturé.
Les archives et les WAL actifs sont sur deux systèmes de fichiers différents, celui des archives a été taillé pour contenir le volume adéquat entre deux sauvegardes, mais pas celui des WAL actifs (respectivement 100 Go et 8 Go).
J'ai donc deux questions à ce propos :
1) il semblerait que la procédure de restauration de postgreSQL (lancement de l'instance avec un fichier recovery.conf contenant le paramètre restore_command = 'cp ${Repertoire_archives}/%f %p') commence par copier tous les fichiers WAL du répertoire d'archive vers le répertoire des fichiers actifs, et ne les recycle ni supprime avant la fin de la restauration. Pouvez-vous me confirmer ce mécanisme par défaut ?
2) Y a-t-il moyen de limiter la taille de l'espace occupé par les fichiers journaux de transaction pendant la restauration, sachant que l'espace disponible pour pg_xlog suffit pour un fonctionnement ordinaire ?
Précision : la version utilisée lors de l'incident est une 9.4, mais il semblerait que le fonctionnement ne soit pas différent sur une v9.6.
Merci par avance,
comaco
Dernière modification par comaco (26/02/2018 11:40:42)
Hors ligne
1. Non, ça ne se passe pas ainsi. Il récupère un fichier et le traite immédiatement. Ceci fait, il passe au suivant. Quand arrive le restartpoint (dépendant de votre configuration), il supprime les fichiers devenus inutiles.
2. Le seul moyen de limiter l'espace pris est de configurer les paramètres checkpoint_timeout et checkpoint_segments.
Guillaume.
Hors ligne
Bonjour,
2. Le seul moyen de limiter l'espace pris est de configurer les paramètres checkpoint_timeout et checkpoint_segments.
Pouvez-vous nous en dire plus sur ce point ?
Parce que je suis comme comaco (dans le floue), si j'ai 200G d'archives ça veut dire que je dois prévoir 200G dans pg_xlog pour faire une restauration ?
Cordialement,
Cordialement,
Sébastien.
Hors ligne
Les restartpoint sont exécutés sur la même fréquence que les checkpoints. Donc c'est lié à la configuration de checkpoint_timeout (5 minutes par défaut) et de checkpoint_segments (3 par défaut), à condition évidemment que le checkpointer arrive à tenir le rythme.
En règle générale, vous n'aurez pas besoin de plus d'espace que sur le serveur sauvegardé. En tout cas, une chose est sûre, vous n'avez pas besoin de 200 Go dans pg_xlog si vous avez 200 Go d'archives à rejouer. Pourquoi comaco a eu un problème, aucune idée. Il faudrait qu'il nous en dise plus (nous fournisse par exemple le log de PostgreSQL pendant la restauration) pour qu'on puisse se prononcer.
Guillaume.
Hors ligne
Je ne peux pas vous donner la trace, il s'agit d'un environnement de pré-production.
Les paramètres utilisés devaient être ceux par défaut pour nous : checkpoint_segments = 10, checkpoint_timeout = 5min.
Nous faisons des essais de reproduction sur nos serveurs de tests, avec plusieurs valeurs du couple
(checkpoint_segments, checkpoint_timeout).
Tests effectués : (5, 5min), (4, 4min),
Tests en cours : (3,30s), (3, 3min)
Procédure de test : 1°)sauvegarde à chaud avec pg_base_backup, 2°) création d'activité sur une base pout une génération d'une grande quantité de WAL 3°) restauration. Surveillance du répertoire 'pg_xlog' pendant les deux dernières phases.
Premiers constats :
- pendant la phase 2, les fichiers WAL ne sont jamais plus de 25 dans le répertoire 'pg_xlog', ils sont archivés au fur et à mesure, les "checkpoints" sont très nombreux (messages dans la trace)
- pendant la phase 3, les fichiers WAL utilisés pour la restauration sont copiés un à un du répertoire d'archives vers 'pg_xlog', comme l'a écrit très justement gleu,
- les fichiers s'accumulent dans le répertoire 'pg_xlog', jusqu'à être plus de 730. Leur nombre redescend à 130-150 lorsque la restauration se termine,
- les "restartpoint", d'après la trace, sont déclenchés exactement au bout d'un délai égal à checkpoint_timeout, le paramètre checkpoint_segments semeble ne pas intervenir (valeurs mal choisies ?)
- lors d'un "restartpoint", aucun fichier ne semble être supprimé de 'pg_xlog'.
Extrait d'une trace :
---------------------------
user=,db=,time=2018-02-14 19:21:44 CET LOG: database system was interrupted; last known up at 2018-02-14 18:17:54 CET
user=,db=,time=2018-02-14 19:21:44 CET LOG: starting point-in-time recovery to 2018-02-14 18:10:00+01
user=,db=,time=2018-02-14 19:21:45 CET LOG: restored log file "00000001000000360000005F" from archive
user=,db=,time=2018-02-14 19:21:45 CET LOG: restored log file "00000001000000360000005B" from archive
user=,db=,time=2018-02-14 19:21:45 CET LOG: redo starts at 36/5B3FC8C8
user=,db=,time=2018-02-14 19:21:45 CET LOG: restored log file "00000001000000360000005C" from archive
[...]
user=,db=,time=2018-02-14 19:25:45 CET LOG: restored log file "00000001000000380000003B" from archive
user=,db=,time=2018-02-14 19:25:45 CET LOG: restartpoint starting: time
user=,db=,time=2018-02-14 19:25:45 CET LOG: restored log file "00000001000000380000003C" from archive
[...]
user=,db=,time=2018-02-14 19:26:20 CET LOG: restored log file "00000001000000380000009B" from archive
user=,db=,time=2018-02-14 19:26:21 CET LOG: could not link file "pg_xlog/xlogtemp.14917" to "pg_xlog/00000001000000380000009B
": File exists
user=,db=,time=2018-02-14 19:26:21 CET LOG: restartpoint complete: wrote 19053 buffers (18.6%); 1 transaction log file(s) added, 0 removed, 0 recycled; write=35.288 s, sync=0.099 s, total=35.549 s; sync files=8, longest=0.038 s, average=0.012 s
user=,db=,time=2018-02-14 19:26:21 CET LOG: recovery restart point at 38/351459D0
user=,db=,time=2018-02-14 19:26:21 CET LOG: restored log file "00000001000000380000009C" from archive
user=,db=,time=2018-02-14 19:26:21 CET LOG: restored log file "00000001000000380000009C" from archive
user=,db=,time=2018-02-14 19:26:21 CET LOG: restored log file "00000001000000380000009D" from archive
user=,db=,time=2018-02-14 19:26:22 CET LOG: restored log file "00000001000000380000009E" from archive
[...]----------------------------
Hors ligne
Tout ce que je peux dire sur cette trace...
1. on n'y voit qu'un seul restartpoint
2. ce restartpoint est déclenché par un dépassement du checkpoint_timeout (message "restartpoint starting: time'... ça aurait été "restartpoint starting: xlog" en cas de dépassement du checkpoint_segments)
3. aucun fichier WAL n'a été supprimé pendant le restartpoint (message "0 removed")
Guillaume.
Hors ligne
Après vérification dans le code, vous pouvez configurer log_min_messages à DEBUG2 pour avoir plus d'infos et notamment des traces du type "attempting to remove WAL segments older than log file %s". Ça permettrait déjà de savoir s'il va bien dans la fonction de suppression des anciens WAL. (attention, DEBUG2, ça fait beaucoup de traces)
Guillaume.
Hors ligne
donc on a bien une accumulation d'archives dans pg_xlog (jusqu'à 730 dans le cas présent).
C'est embêtant...
Y a t'il un moyen pour limiter ce phénomène ?
J'ai rencontré ce cas récemment en production. Heureusement pour moi les volumétries n'étaient pas aussi importantes.
Dernière modification par ruizsebastien (15/02/2018 12:10:41)
Cordialement,
Sébastien.
Hors ligne
Nouveaux tests avec valeurs plus petites des deux paramètres : plusieurs "restartpoint" sont indiqués dans les traces pendant la restauration.
Le premier restartpoint ne fait rien sur le fichiers WAL, les suivants opère des suppressions et recyclages.
Mais avec mes données, le nombre de fichiers dans pg_xlog reste bien supérieur à celui que l'on observe lors de l'activité "normale" de la base :
avec le couple de paramètres (2,2min), le nombre de fichiers évolue entre 657 (max observé) et 201 (en fin de restauration).
Les traces avec DEBUG2 sont assez volumineuses, je ne copie que des (gros) extraits ci-dessous. A noter : mon instance est sur une ligne de temps de 2, alors que la sauvegarde est sur une ligne de temps de 1, d'où des messages supplémentaire "cp: cannot stat" dans la trace.
Les lignes vides ont été ajoutées pour la lecture.
[...]
cp: cannot stat `/rep_archives/000000020000003E000000FD': No such file or directory
user=,db=,time=2018-02-15 14:21:57 CET DEBUG: could not restore file "000000020000003E000000FD" from archive: child process exited with exit code 1
user=,db=,time=2018-02-15 14:21:57 CET LOG: restored log file "000000010000003E000000FD" from archive
user=,db=,time=2018-02-15 14:21:57 CET DEBUG: got WAL segment from archive
cp: cannot stat `/rep_archives/000000020000003E000000FE': No such file or directory
user=,db=,time=2018-02-15 14:21:58 CET DEBUG: could not restore file "000000020000003E000000FE" from archive: child process exited with exit code 1
user=,db=,time=2018-02-15 14:21:58 CET LOG: restored log file "000000010000003E000000FE" from archive
user=,db=,time=2018-02-15 14:21:58 CET DEBUG: got WAL segment from archive
user=,db=,time=2018-02-15 14:21:58 CET LOG: restartpoint starting: time
user=,db=,time=2018-02-15 14:21:58 CET DEBUG: performing replication slot checkpoint
user=,db=,time=2018-02-15 14:21:58 CET DEBUG: updated min recovery point to 3E/FEE99610 on timeline 1
user=,db=,time=2018-02-15 14:21:58 CET CONTEXT: writing block 43418 of relation base/26764/26777
cp: cannot stat `/rep_archives/000000020000003E000000FF': No such file or directory
user=,db=,time=2018-02-15 14:21:58 CET DEBUG: could not restore file "000000020000003E000000FF" from arc
hive: child process exited with exit code 1
user=,db=,time=2018-02-15 14:21:58 CET LOG: restored log file "000000010000003E000000FF" from archive
user=,db=,time=2018-02-15 14:21:58 CET DEBUG: got WAL segment from archive
cp: cannot stat `/rep_archives/000000020000003F00000000': No such file or directory
user=,db=,time=2018-02-15 14:21:58 CET DEBUG: could not restore file "000000020000003F00000000" from archive: child process exited with exit code 1
user=,db=,time=2018-02-15 14:21:58 CET LOG: restored log file "000000010000003F00000000" from archive
user=,db=,time=2018-02-15 14:21:58 CET DEBUG: got WAL segment from archive
user=,db=,time=2018-02-15 14:21:58 CET DEBUG: updated min recovery point to 3F/9E8668 on timeline 1
user=,db=,time=2018-02-15 14:21:58 CET CONTEXT: writing block 39106 of relation base/26764/26777
[...]
user=,db=,time=2018-02-15 14:22:38 CET LOG: restored log file "000000010000003F0000006B" from archive
user=,db=,time=2018-02-15 14:22:38 CET DEBUG: checkpoint sync: number=1 file=base/26764/12753 time=86.241 msec
user=,db=,time=2018-02-15 14:22:38 CET DEBUG: checkpoint sync: number=2 file=base/26764/12753_fsm time=37.491 msec
user=,db=,time=2018-02-15 14:22:38 CET DEBUG: checkpoint sync: number=3 file=base/26764/26815 time=8.021 msec
user=,db=,time=2018-02-15 14:22:38 CET DEBUG: checkpoint sync: number=4 file=base/17259/26789.2 time=0.106 msec
[...]
user=,db=,time=2018-02-15 14:22:39 CET DEBUG: checkpoint sync: number=59 file=base/26764/12755 time=0.057 msec
user=,db=,time=2018-02-15 14:22:39 CET DEBUG: attempting to remove WAL segments older than log file 000000000000003D000000FD
user=,db=,time=2018-02-15 14:22:39 CET DEBUG: SlruScanDirectory invoking callback on pg_multixact/offsets/0000
user=,db=,time=2018-02-15 14:22:39 CET DEBUG: SlruScanDirectory invoking callback on pg_multixact/members/0000
user=,db=,time=2018-02-15 14:22:39 CET DEBUG: SlruScanDirectory invoking callback on pg_multixact/offsets/0000
user=,db=,time=2018-02-15 14:22:39 CET LOG: restartpoint complete: wrote 42981 buffers (42.0%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=40.107 s,
sync=0.727 s, total=40.892 s; sync files=59, longest=0.478 s, average=0.011 s
user=,db=,time=2018-02-15 14:22:39 CET LOG: recovery restart point at 3E/F90157D8
user=,db=,time=2018-02-15 14:22:39 CET DETAIL: last completed transaction was at log time 2018-02-14 20:44:22.884051+01
cp: cannot stat `/rep_archives/000000020000003F0000006C': No such file or directory
user=,db=,time=2018-02-15 14:22:39 CET DEBUG: could not restore file "000000020000003F0000006C" from archive: child process exited with exit code 1
user=,db=,time=2018-02-15 14:22:39 CET LOG: restored log file "000000010000003F0000006C" from archive
user=,db=,time=2018-02-15 14:22:39 CET DEBUG: got WAL segment from archive
[...]
user=,db=,time=2018-02-15 14:22:53 CET LOG: restored log file "000000010000003F00000090" from archive
user=,db=,time=2018-02-15 14:22:54 CET DEBUG: got WAL segment from archive
user=,db=,time=2018-02-15 14:22:54 CET DEBUG: updated min recovery point to 3F/90617B48 on timeline 1
user=,db=,time=2018-02-15 14:22:54 CET CONTEXT: writing block 20660 of relation base/26764/26777
xlog redo insert(init): rel 1663/26764/26818; tid 43344/1
cp: cannot stat `/rep_archives/000000020000003F00000091': No such file or directory
user=,db=,time=2018-02-15 14:22:54 CET DEBUG: could not restore file "000000020000003F00000091" from archive: child process exited with exit code 1
user=,db=,time=2018-02-15 14:22:54 CET LOG: restored log file "000000010000003F00000091" from archive
user=,db=,time=2018-02-15 14:22:54 CET DEBUG: got WAL segment from archive
user=,db=,time=2018-02-15 14:22:54 CET DEBUG: updated min recovery point to 3F/912A5410 on timeline 1
user=,db=,time=2018-02-15 14:22:54 CET CONTEXT: xlog redo file truncate: base/26764/26774 to 271 blocks
user=,db=,time=2018-02-15 14:22:54 CET DEBUG: updated min recovery point to 3F/912BC110 on timeline 1
user=,db=,time=2018-02-15 14:22:54 CET CONTEXT: xlog redo file truncate: base/26764/26768 to 325 blocks
user=,db=,time=2018-02-15 14:22:54 CET DEBUG: updated min recovery point to 3F/912C1ED8 on timeline 1
user=,db=,time=2018-02-15 14:22:54 CET CONTEXT: xlog redo commit: 2018-02-14 20:45:14.433772+01; rels: base/26764/26822
cp: cannot stat `/rep_archives/000000020000003F00000092': No such file or directory
user=,db=,time=2018-02-15 14:22:54 CET DEBUG: could not restore file "000000020000003F00000092" from archive: child process exited with exit code 1
user=,db=,time=2018-02-15 14:22:55 CET LOG: restored log file "000000010000003F00000092" from archive
[...]
user=,db=,time=2018-02-15 14:23:15 CET LOG: restored log file "000000010000003F000000C6" from archive
user=,db=,time=2018-02-15 14:23:15 CET DEBUG: got WAL segment from archive
user=,db=,time=2018-02-15 14:23:16 CET DEBUG: updated min recovery point to 3F/C6F9C870 on timeline 1
user=,db=,time=2018-02-15 14:23:16 CET CONTEXT: writing block 978 of relation base/26764/26777
[...]
user=,db=,time=2018-02-15 14:23:26 CET DEBUG: got WAL segment from archive
user=,db=,time=2018-02-15 14:23:26 CET DEBUG: updated min recovery point to 3F/E0D5B720 on timeline 1
user=,db=,time=2018-02-15 14:23:26 CET CONTEXT: writing block 55064 of relation base/26764/26777
xlog redo visible: rel 1663/17259/26789; blk 661991
cp: cannot stat `/rep_archives/000000020000003F000000E1': No such file or directory
user=,db=,time=2018-02-15 14:23:26 CET DEBUG: could not restore file "000000020000003F000000E1" from archive: child process exited with exit code 1
user=,db=,time=2018-02-15 14:23:26 CET LOG: restored log file "000000010000003F000000E1" from archive
user=,db=,time=2018-02-15 14:23:26 CET DEBUG: got WAL segment from archive
[...]
user=,db=,time=2018-02-15 14:23:31 CET DEBUG: updated min recovery point to 3F/ED452BE0 on timeline 1
user=,db=,time=2018-02-15 14:23:31 CET CONTEXT: writing block 13717 of relation base/26764/26777
xlog redo insert(init): rel 1663/26764/26818; tid 56460/1
[...]
user=,db=,time=2018-02-15 14:23:36 CET DEBUG: updated min recovery point to 3F/F80D9890 on timeline 1
user=,db=,time=2018-02-15 14:23:36 CET CONTEXT: writing block 60428 of relation base/26764/26777
[...]
user=,db=,time=2018-02-15 14:23:51 CET DEBUG: updated min recovery point to 40/19776070 on timeline 1
user=,db=,time=2018-02-15 14:23:51 CET CONTEXT: writing block 27822 of relation base/26764/26777
xlog redo visible: rel 1663/17259/26789; blk 673963
[...]
user=,db=,time=2018-02-15 14:23:58 CET LOG: restartpoint starting: time
user=,db=,time=2018-02-15 14:23:58 CET DEBUG: performing replication slot checkpoint
user=,db=,time=2018-02-15 14:23:58 CET DEBUG: updated min recovery point to 40/2B540F60 on timeline 1
user=,db=,time=2018-02-15 14:23:58 CET CONTEXT: writing block 79343 of relation base/26764/26777
cp: cannot stat `/rep_archives/00000002000000400000002C': No such file or directory
user=,db=,time=2018-02-15 14:23:58 CET DEBUG: could not restore file "00000002000000400000002C" from archive: child process exited with exit code 1
user=,db=,time=2018-02-15 14:23:59 CET LOG: restored log file "00000001000000400000002C" from archive
user=,db=,time=2018-02-15 14:23:59 CET DEBUG: got WAL segment from archive
ser=,db=,time=2018-02-15 14:23:59 CET DEBUG: updated min recovery point to 40/2CBDE180 on timeline 1
user=,db=,time=2018-02-15 14:23:59 CET CONTEXT: writing block 63680 of relation base/26764/26777
[...]
user=,db=,time=2018-02-15 14:24:01 CET LOG: restored log file "000000010000004000000030" from archive
user=,db=,time=2018-02-15 14:24:01 CET DEBUG: got WAL segment from archive
user=,db=,time=2018-02-15 14:24:01 CET DEBUG: updated min recovery point to 40/305125C0 on timeline 1
user=,db=,time=2018-02-15 14:24:01 CET CONTEXT: writing block 10 of relation base/26764/26778
[...]
user=,db=,time=2018-02-15 14:24:02 CET DEBUG: updated min recovery point to 40/34000000 on timeline 1
user=,db=,time=2018-02-15 14:24:02 CET CONTEXT: writing block 11001 of relation base/26764/26777
[...]
user=,db=,time=2018-02-15 14:24:03 CET DEBUG: updated min recovery point to 40/35FFFFE8 on timeline 1
user=,db=,time=2018-02-15 14:24:03 CET CONTEXT: writing block 69080 of relation base/26764/26777
[...]
user=,db=,time=2018-02-15 14:24:53 CET LOG: restored log file "0000000100000040000000A8" from archive
user=,db=,time=2018-02-15 14:24:53 CET DEBUG: checkpoint sync: number=1 file=base/26764/12753 time=42.457 msec
user=,db=,time=2018-02-15 14:24:53 CET DEBUG: checkpoint sync: number=2 file=base/26764/12753_fsm time=1.696 msec
[...]
user=,db=,time=2018-02-15 14:24:53 CET DEBUG: checkpoint sync: number=31 file=base/26764/12755 time=0.062 msec
user=,db=,time=2018-02-15 14:24:53 CET DEBUG: attempting to remove WAL segments older than log file 000000000000003E000000F8
user=,db=,time=2018-02-15 14:24:53 CET DEBUG: recycled transaction log file "000000010000003E00000071"
user=,db=,time=2018-02-15 14:24:53 CET DEBUG: recycled transaction log file "000000010000003E00000086"
user=,db=,time=2018-02-15 14:24:53 CET DEBUG: recycled transaction log file "000000010000003E00000049"
[...]
user=,db=,time=2018-02-15 14:24:53 CET DEBUG: recycled transaction log file "000000010000003E00000056"
user=,db=,time=2018-02-15 14:24:53 CET DEBUG: removing transaction log file "000000010000003E000000F4"
user=,db=,time=2018-02-15 14:24:53 CET DEBUG: removing transaction log file "000000010000003E0000005D"
[...]
user=,db=,time=2018-02-15 14:24:54 CET DEBUG: removing transaction log file "000000010000003E000000A0"
user=,db=,time=2018-02-15 14:24:54 CET DEBUG: SlruScanDirectory invoking callback on pg_multixact/offsets/0000
user=,db=,time=2018-02-15 14:24:54 CET DEBUG: SlruScanDirectory invoking callback on pg_multixact/members/0000
user=,db=,time=2018-02-15 14:24:54 CET DEBUG: SlruScanDirectory invoking callback on pg_multixact/offsets/0000
user=,db=,time=2018-02-15 14:24:54 CET LOG: restartpoint complete: wrote 58941 buffers (57.6%); 0 transaction log file(s) added, 245 removed, 6 recycled; write=54.597 s,
sync=0.158 s, t
otal=55.257 s; sync files=31, longest=0.078 s, average=0.004 s
user=,db=,time=2018-02-15 14:24:54 CET LOG: recovery restart point at 40/2407EB88
user=,db=,time=2018-02-15 14:24:54 CET DETAIL: last completed transaction was at log time 2018-02-14 20:47:35.815539+01
[...]
user=,db=,time=2018-02-15 14:25:01 CET DEBUG: transaction ID wrap limit is 2147485445, limited by database with OID 1
user=,db=,time=2018-02-15 14:25:01 CET CONTEXT: xlog redo checkpoint: redo 40/BC000028; tli 2; prev tli 1; fpw true; xid 0/624391; oid 34984; multi 1; offset 0; oldest xid
1798 in DB 1;
oldest multi 1 in DB 17259; oldest running xid 0; shutdown
user=,db=,time=2018-02-15 14:25:01 CET DEBUG: MultiXactId wrap limit is 2147483648, limited by database with OID 17259
user=,db=,time=2018-02-15 14:25:01 CET CONTEXT: xlog redo checkpoint: redo 40/BC000028; tli 2; prev tli 1; fpw true; xid 0/624391; oid 34984; multi 1; offset 0; oldest xid
1798 in DB 1;
oldest multi 1 in DB 17259; oldest running xid 0; shutdown
user=,db=,time=2018-02-15 14:25:01 CET DEBUG: attempting to remove WAL segments newer than log file 0000000200000040000000BC
user=,db=,time=2018-02-15 14:25:01 CET LOG: restored log file "0000000200000040000000BD" from archive
user=,db=,time=2018-02-15 14:25:01 CET DEBUG: got WAL segment from archive
[...]
user=,db=,time=2018-02-15 14:25:58 CET LOG: restartpoint starting: time
user=,db=,time=2018-02-15 14:25:58 CET DEBUG: performing replication slot checkpoint
user=,db=,time=2018-02-15 14:25:58 CET LOG: restored log file "00000002000000410000002A" from archive
user=,db=,time=2018-02-15 14:25:58 CET DEBUG: updated min recovery point to 41/29FFE3A0 on timeline 2
user=,db=,time=2018-02-15 14:25:58 CET CONTEXT: writing block 99174 of relation base/26764/26818
[...]
user=,db=,time=2018-02-15 14:26:21 CET DEBUG: checkpoint sync: number=1 file=base/26764/26815 time=166.765 msec
user=,db=,time=2018-02-15 14:26:21 CET DEBUG: checkpoint sync: number=2 file=base/17259/26789.5 time=4.183 msec
[...]
user=,db=,time=2018-02-15 14:26:21 CET DEBUG: checkpoint sync: number=30 file=base/26764/26804_vm time=0.818 msec
user=,db=,time=2018-02-15 14:26:21 CET DEBUG: attempting to remove WAL segments older than log file 000000000000004000000023
user=,db=,time=2018-02-15 14:26:21 CET DEBUG: recycled transaction log file "000000010000003F000000A0"
[...]
user=,db=,time=2018-02-15 14:26:21 CET DEBUG: recycled transaction log file "000000010000003F00000056"
user=,db=,time=2018-02-15 14:26:21 CET DEBUG: removing transaction log file "000000010000003F000000BB"
[...]
user=,db=,time=2018-02-15 14:26:24 CET DEBUG: removing transaction log file "000000010000003F00000097"
user=,db=,time=2018-02-15 14:26:24 CET DEBUG: SlruScanDirectory invoking callback on pg_multixact/offsets/0000
user=,db=,time=2018-02-15 14:26:24 CET DEBUG: SlruScanDirectory invoking callback on pg_multixact/members/0000
user=,db=,time=2018-02-15 14:26:24 CET DEBUG: SlruScanDirectory invoking callback on pg_multixact/offsets/0000
user=,db=,time=2018-02-15 14:26:24 CET LOG: restartpoint complete: wrote 24641 buffers (24.1%); 0 transaction log file(s) added, 291 removed, 8 recycled; write=23.032 s,
sync=0.429 s, t
otal=26.524 s; sync files=30, longest=0.169 s, average=0.014 s
user=,db=,time=2018-02-15 14:26:24 CET LOG: recovery restart point at 41/24613220
user=,db=,time=2018-02-15 14:26:24 CET DETAIL: last completed transaction was at log time 2018-02-14 21:13:29.676208+01
user=,db=,time=2018-02-15 14:26:24 CET LOG: restored log file "000000020000004100000071" from archive
[...]
user=,db=,time=2018-02-15 14:27:04 CET LOG: selected new timeline ID: 3
user=,db=,time=2018-02-15 14:27:04 CET LOG: restored log file "00000002.history" from archive
user=,db=,time=2018-02-15 14:27:04 CET DEBUG: updated min recovery point to 41/E3FFFEA0 on timeline 2
user=,db=,time=2018-02-15 14:27:04 CET LOG: archive recovery complete
user=,db=,time=2018-02-15 14:27:04 CET LOG: checkpoint starting: end-of-recovery immediate wait
[...]
user=,db=,time=2018-02-15 14:27:10 CET DEBUG: attempting to remove WAL segments older than log file 000000000000004100000023
[...]
user=,db=,time=2018-02-15 14:27:11 CET DEBUG: removing transaction log file "000000020000004100000004"
user=,db=,time=2018-02-15 14:27:11 CET DEBUG: SlruScanDirectory invoking callback on pg_multixact/offsets/0000
user=,db=,time=2018-02-15 14:27:11 CET DEBUG: SlruScanDirectory invoking callback on pg_multixact/members/0000
user=,db=,time=2018-02-15 14:27:11 CET DEBUG: SlruScanDirectory invoking callback on pg_multixact/offsets/0000
user=,db=,time=2018-02-15 14:27:11 CET LOG: checkpoint complete: wrote 102088 buffers (99.7%); 0 transaction log file(s) added, 251 removed, 5 recycled; write=1.901 s,
sync=4.649 s, tot
al=7.294 s; sync files=39, longest=1.909 s, average=0.115 s
user=,db=,time=2018-02-15 14:27:11 CET DEBUG: attempting to remove WAL segments newer than log file 0000000300000041000000E3
user=,db=,time=2018-02-15 14:27:11 CET DEBUG: oldest MultiXactId member is at offset 0
user=,db=,time=2018-02-15 14:27:11 CET LOG: MultiXact member wraparound protections are now enabled
user=,db=,time=2018-02-15 14:27:11 CET DEBUG: MultiXact member stop limit is now 4294914944 based on MultiXact 1
user=,db=,time=2018-02-15 14:27:11 CET LOG: database system is ready to accept connectionsHors ligne
On voit bien qu'il les supprime ("removing transaction log file ..." et "wrote ... buffers (...%); ... transaction log file(s) added, 291 removed"). Donc il n'attend pas la fin de la restauration pour les supprimer. Difficile d'en dire plus, surtout avec un fichier de traces fortement édité.
Guillaume.
Hors ligne
Désolée pour la trace incomplète, mais je ne sais pas comment annexer un fichier à un message de forum, et le fichier fait près de 5000 lignes (514 Ko), donc je ne peux pas copier tout le contenu. J'ai éliminé des lignes qui étaient du même type que celles déjà citées dans cette discussion, en essayant de garder les messages significatifs.
Pour finir, ce que je conclus de nos tests et de cette discussion :
-*- le nombre de fichiers présents dans pg_xlog pendant une restauration, et juste après, peut être bien supérieur à ce qu'il est pendant un fonctionnement normal
-*- le paramètre 'checkpoint_timeout' permet de limiter le nombre de fichiers, puisqu'il provoque l'exécution des "restartpoint"
-*- le nombre maximal de fichiers dans le répertoire n'est pas calculable aisément à partir des paramètres de configuration : il dépend du nombre de fichiers WAL d'archives traités pendant la durée entre deux "restartpoint", et du nombre de fichiers supprimés lors de chacune de ces opérations, qui relève du mécanisme interne de postgreSQL, sans doute assez complexe (et le premier restartpoint ne fait rien sur ce point).
Au final, il vaut mieux prévoir un espace assez conséquent pour les fichiers de journaux de transactions actifs pendant la restauration, car le rejeu des fichiers récupérés dans l'archive est très rapide (beaucoup de fichiers sont "consommés" entre deux "restartpoint").
Hors ligne
Il n'est pas possible de joindre un fichier au forum, désolé.
-*- le nombre de fichiers présents dans pg_xlog pendant une restauration, et juste après, peut être bien supérieur à ce qu'il est pendant un fonctionnement normal
Tout à fait.
-*- le paramètre 'checkpoint_timeout' permet de limiter le nombre de fichiers, puisqu'il provoque l'exécution des "restartpoint"
Exact.
-*- le nombre maximal de fichiers dans le répertoire n'est pas calculable aisément à partir des paramètres de configuration : il dépend du nombre de fichiers WAL d'archives traités pendant la durée entre deux "restartpoint", et du nombre de fichiers supprimés lors de chacune de ces opérations, qui relève du mécanisme interne de postgreSQL, sans doute assez complexe (et le premier restartpoint ne fait rien sur ce point).
Il n'est pas calculable aisément parce que c'est tout simplement impossible. PostgreSQL ne fournit aucune garantie sur la taille maximale du pg_xlog dans quelques configurations que ce soit. Je veux dire par là que c'est vrai pour une restauration, mais c'est vrai aussi dans le cas normal d'utilisation. En configurant un espace restreint, vous prenez un risque. C'est d'ailleurs pour cela que je conseille en permanence en formation que la taille de la partition contenant les WAL ne soit pas exactement la valeur de la formule habituelle (3*checkpoint_segments + 1). C'est aussi pour cela que je conseille de superviser la taille de cette partition.
Au final, il vaut mieux prévoir un espace assez conséquent pour les fichiers de journaux de transactions actifs pendant la restauration, car le rejeu des fichiers récupérés dans l'archive est très rapide (beaucoup de fichiers sont "consommés" entre deux "restartpoint").
Oui.
Guillaume.
Hors ligne