Vous n'êtes pas identifié(e).
Bonjour à tous(tes),
Depuis un moment, je rencontre des logs importants dans /var/log/postgresql/postgresql-11-main.log lors de l'arrêt du service postgresql ; Et aussi parfois, lors du démarrage sur le serveur maître de réplication.
--
Ca peut prendre 30 minutes avant l'arrêt effectif du service (ou le start).
--
Version postgresql : v11
Version Debian : 9.11
--
Je cherche mais je ne trouve pas la raison.
--
Le serveur est maître de réplication (1 maître).
5 serveurs sont synchronisés par des souscriptions aux abonnements. 53 tables par serveurs.
--
Voici le log succinct lors de la commande "service postgresql stop" : (des milliers de lignes de ce type ...)
--
2021-10-28 19:21:52.726 GMT [10994] logrepli@ppv FATAL: le système de base de données s'arrête
2021-10-28 19:21:52.765 GMT [11037] logrepli@ppv FATAL: le système de base de données s'arrête
2021-10-28 19:21:52.766 GMT [11038] logrepli@ppv FATAL: le système de base de données s'arrête
--
Sinon la réplication fonctionne bien une fois postgresql actif.
J'ai dû loupé quelque chose ...
--
Toute l'aide sera la bienvenue,
--
merci,
Cdlt,
Olivier
Dernière modification par OlivierMans (28/10/2021 22:22:52)
Hors ligne
Voici quelques éléments du postgresql.conf : (pas tout)
data_directory = '/var/lib/postgresql/11/main' # use data in another directory
# (change requires restart)
hba_file = '/etc/postgresql/11/main/pg_hba.conf' # host-based authentication file
# (change requires restart)
ident_file = '/etc/postgresql/11/main/pg_ident.conf' # ident configuration file
# (change requires restart)
# If external_pid_file is not explicitly set, no extra PID file is written.
external_pid_file = '/var/run/postgresql/11-main.pid' # write an extra PID file
# (change requires restart)
#------------------------------------------------------------------------------
# CONNECTIONS AND AUTHENTICATION
#------------------------------------------------------------------------------
# - Connection Settings -
#listen_addresses = 'localhost' # what IP address(es) to listen on;
listen_addresses = '*' # what IP address(es) to listen on;
# comma-separated list of addresses;
# defaults to 'localhost'; use '*' for all
# (change requires restart)
#port = 5433 # (change requires restart)
port = 5432 # (change requires restart)
#max_connections = 100 # (change requires restart)
max_connections = 500
------------------------------------
# - Settings -
#wal_level = replica # minimal, replica, or logical
#ici on active la réaplication logique
wal_level = logical # minimal, replica, or logical
# (change requires restart)
#fsync = on # flush data to disk for crash safety
# (turning this off can cause
# unrecoverable data corruption)
#synchronous_commit = on # synchronization level;
# off, local, remote_write, remote_apply, or on
#wal_sync_method = fsync # the default is the first option
# supported by the operating system:
# open_datasync
# fdatasync (default on Linux and FreeBSD)
# fsync
# fsync_writethrough
# open_sync
#full_page_writes = on # recover from partial page writes
#wal_compression = off # enable compression of full-page writes
#wal_log_hints = off # also do full page writes of non-critical updates
# (change requires restart)
#wal_buffers = -1 # min 32kB, -1 sets based on shared_buffers
# (change requires restart)
#wal_writer_delay = 200ms # 1-10000 milliseconds
#wal_writer_flush_after = 1MB # measured in pages, 0 disables
#commit_delay = 0 # range 0-100000, in microseconds
#commit_siblings = 5 # range 1-1000
# - Checkpoints -
#checkpoint_timeout = 5min # range 30s-1d
max_wal_size = 1GB
min_wal_size = 80MB
#checkpoint_completion_target = 0.5 # checkpoint target duration, 0.0 - 1.0
#checkpoint_flush_after = 256kB # measured in pages, 0 disables
#checkpoint_warning = 30s # 0 disables
Hors ligne
j'ajoute que j'ai suivi cette documentation pour mettre en place la réplication logique :
https://public.dalibo.com/exports/forma … ndout.html
Hors ligne
Peut-être une piste, est-ce que lors de l'arrêt du service Postgresql, le service a du mal a killer les connexions des serveurs distants au serveur Maître de réplication ?????
Ici la commande ps -aux renvoi toutes les connexions des serveurs synchronisés (a l'heure actuelle 256 processus) :
postgres 2984 0.0 0.0 629456 4656 ? Ss 20:08 0:00 postgres: 11/main: logical replication launcher
postgres 2985 0.0 0.2 630124 19520 ? Ss 20:08 0:00 postgres: 11/main: walsender logrepli 192.168.94.100(49652) idle
postgres 2986 0.0 0.2 630160 18320 ? Ss 20:08 0:00 postgres: 11/main: walsender logrepli 192.168.94.100(49650) idle
postgres 2987 0.0 0.2 630124 19584 ? Ss 20:08 0:00 postgres: 11/main: walsender logrepli 192.168.94.100(49654) idle
postgres 2988 0.0 0.2 630124 19532 ? Ss 20:08 0:00 postgres: 11/main: walsender logrepli 192.168.94.100(49656) idle
postgres 2989 0.0 0.2 630124 19596 ? Ss 20:08 0:00 postgres: 11/main: walsender logrepli 192.168.94.100(49658) idle
postgres 2990 0.0 0.2 630160 18320 ? Ss 20:08 0:00 postgres: 11/main: walsender logrepli 192.168.94.100(49660) idle
postgres 2991 0.0 0.2 630120 19596 ? Ss 20:08 0:00 postgres: 11/main: walsender logrepli 192.168.94.100(49662) idle
Hors ligne
Bonjour,
À priori le problème vient de la façon dont vous arrêtez votre instance. Les messages de type "FATAL: le système de base de données s'arrête" indique qu'un arrêt de type "smart" (plutôt mal nommé) à été demandé, cf https://www.postgresql.org/docs/current/app-pg-ctl.html. Le mode "smart" empêche toute nouvelle connection à l'instance (avec ce message) et attends que toutes les connexions existantes se terminent. Dans votre cas, il faut croire que des connexions restent ouverte pendant 30 minutes, ce qui n'a rien d'étonnant.
Vous devriez arrêter votre instance avec le mode "fast", ce qui force la déconnexion de toutes les sessions et accélère donc grandement l'arrêt.
Julien.
https://rjuju.github.io/
Hors ligne
Bonsoir Julien,
Merci beaucoup, effectivement, je pense que vous avez raison.
Juste le temps de chercher où positionner cet argument lors de l'appel à la commande "service postgresql stop".
Je ferai un retour ASAP.
Cdlt,
Olivier
Dernière modification par OlivierMans (29/10/2021 18:18:52)
Hors ligne
Bon, je ne pense pas pouvoir positionner ce paramètre au script fourni par l'OS.
J'ai désactivé le démarrage automatique de postgresql via systemd.
J'ai tenté "pg_ctlcluster 11 main stop -m fast" mais c'est la même chose.
j'ai tenté "pg_ctlcluster 11 main stop -m immediate" et là l'arrêt est instantanné.
Je refait quand même un test.
Autre souci, quand je relance après le immediate avec la commande "pg_ctlcluster 11 main start" , j'ai encore une multitude de lignes au démarrage du type :
2021-10-29 17:47:16.867 GMT [29430] logrepli@ppv FATAL: le système de bases de données se lance
2021-10-29 17:47:16.873 GMT [29431] logrepli@ppv FATAL: le système de bases de données se lance
2021-10-29 17:47:16.881 GMT [29432] logrepli@ppv FATAL: le système de bases de données se lance
2021-10-29 17:47:16.882 GMT [29433] logrepli@ppv FATAL: le système de bases de données se lance
J'attend qu'il démarre proprement et je reteste la commande avec Fast.
Hors ligne
Pour le -m immediate, il est normal de voir ces messages. Le mode immediat est en fait un arrêt brutal de l'instance, qui impose de rejouer les journaux de transaction. En règle générale, vous ne devriez jamais utiliser ce mode.
Il est par contre intéressant de voir que l'arrêt en mode "fast" n'est pas plus rapide. La seule raison que je vois à ça serait une connexion bloquée quelque part et qui ne répondrait pas à cette demande d'arrêt rapide. Utilisez-vous des extensions particulières ? Si ce n'est pas le cas, vous pourriez essayer de terminer les processus un part un en utilisant pg_terminate_backend(pid) et voir si certain ne répondent pas, et si c'est le cas ce qu'ils font.
Julien.
https://rjuju.github.io/
Hors ligne
Merci Julien.
J'ai rebooté le serveur.
Relancé postgres via pg_ctl. Cette fois pas de messages.
Je reteste le stop en mode FAST. Ici : 19h36 chez moi
Le log affiche ca :
2021-10-29 19:38:26.107 GMT [13353] logrepli@ppv FATAL: le système de base de données s'arrête
2021-10-29 19:38:26.110 GMT [13354] logrepli@ppv FATAL: le système de base de données s'arrête
etc...
Je vais d'abord mesurer el temps d'arrêt et tester vos propositions.
Non pas d'extensions particulières à ma connaissance (hormis postgis).
Hors ligne
19h50, ca tourne toujours (donc déjà 15 minutes)
2021-10-29 19:50:25.934 GMT [10759] logrepli@ppv FATAL: le système de base de données s'arrête
2021-10-29 19:50:25.935 GMT [10760] logrepli@ppv FATAL: le système de base de données s'arrête
2021-10-29 19:50:25.936 GMT [10761] logrepli@ppv FATAL: le système de base de données s'arrête
2021-10-29 19:50:25.936 GMT [10762] logrepli@ppv FATAL: le système de base de données s'arrête
2021-10-29 19:50:25.946 GMT [10763] logrepli@ppv FATAL: le système de base de données s'arrête
2021-10-29 19:50:25.947 GMT [10764] logrepli@ppv FATAL: le système de base de données s'arrête
2021-10-29 19:50:25.947 GMT [10765] logrepli@ppv FATAL: le système de base de données s'arrête
2021-10-29 19:50:25.948 GMT [10766] logrepli@ppv FATAL: le système de base de données s'arrête
2021-10-29 19:50:25.954 GMT [10767] logrepli@ppv FATAL: le système de base de données s'arrête
2021-10-29 19:50:25.978 GMT [10768] logrepli@ppv FATAL: le système de base de données s'arrête
2021-10-29 19:50:25.979 GMT [10769] logrepli@ppv FATAL: le système de base de données s'arrête
2021-10-29 19:50:25.984 GMT [10770] logrepli@ppv FATAL: le système de base de données s'arrête
2021-10-29 19:50:25.985 GMT [10771] logrepli@ppv FATAL: le système de base de données s'arrête
2021-10-29 19:50:25.989 GMT [10772] logrepli@ppv FATAL: le système de base de données s'arrête
2021-10-29 19:50:25.997 GMT [10773] logrepli@ppv FATAL: le système de base de données s'arrête
2021-10-29 19:50:26.015 GMT [10774] logrepli@ppv FATAL: le système de base de données s'arrête
2021-10-29 19:50:26.021 GMT [10775] logrepli@ppv FATAL: le système de base de données s'arrête
2021-10-29 19:50:26.022 GMT [10776] logrepli@ppv FATAL: le système de base de données s'arrête
2021-10-29 19:50:26.033 GMT [10777] logrepli@ppv FATAL: le système de base de données s'arrête
2021-10-29 19:50:26.049 GMT [10778] logrepli@ppv FATAL: le système de base de données s'arrête
2021-10-29 19:50:26.052 GMT [10779] logrepli@ppv FATAL: le système de base de données s'arrête
2021-10-29 19:50:26.081 GMT [10780] logrepli@ppv FATAL: le système de base de données s'arrête
2021-10-29 19:50:26.090 GMT [10781] logrepli@ppv FATAL: le système de base de données s'arrête
2021-10-29 19:50:26.101 GMT [10782] logrepli@ppv FATAL: le système de base de données s'arrête
2021-10-29 19:50:26.252 GMT [10493] logrepli@ppv FATAL: le système de base de données s'arrête
Hors ligne
Quels sont les processus de PostgreSQL encore vivants ?
Guillaume.
Hors ligne
Je me pose aussi une question, est-ce qu'il est possible que pendant l'arrêt les serveurs distants continuent de tenter des connexions, et donc ca tourne sans fin ...
Simple hypothèse ...
Ou bien postgres n'accepte plus les connexions dès la demande d'arrêt.
Hors ligne
@GLEU : Bonjour Guillaume,
Voici le retour du ps -aux
root@lin01:~# ps -aux |grep postgres
postgres 1809 3.7 0.6 628896 50528 ? S 19:34 0:43 /usr/lib/postgresql/11/bin/postgres -D /var/lib/postgresql/11/main -c config_file=/etc/postgresql/11/main/postgresql.conf
postgres 4125 2.9 0.0 628896 5704 ? Ds 19:35 0:34 postgres: 11/main: checkpointer
postgres 4129 0.0 0.0 59164 4044 ? Ss 19:35 0:00 postgres: 11/main: stats collector
root 4723 0.0 0.0 8688 1984 pts/1 S+ 19:36 0:00 systemctl stop postgresql@11-main
root 31046 0.0 0.0 4724 792 pts/0 S+ 19:54 0:00 grep postgres
postgres 31062 0.0 0.0 628896 6240 ? Ss 19:54 0:00 /usr/lib/postgresql/11/bin/postgres -D /var/lib/postgresql/11/main -c config_file=/etc/postgresql/11/main/postgresql.conf
postgres 31063 0.0 0.0 628896 6240 ? Ss 19:54 0:00 /usr/lib/postgresql/11/bin/postgres -D /var/lib/postgresql/11/main -c config_file=/etc/postgresql/11/main/postgresql.conf
postgres 31064 0.0 0.0 628896 6240 ? Ss 19:54 0:00 /usr/lib/postgresql/11/bin/postgres -D /var/lib/postgresql/11/main -c config_file=/etc/postgresql/11/main/postgresql.conf
postgres 31065 0.0 0.0 628896 6240 ? Ss 19:54 0:00 /usr/lib/postgresql/11/bin/postgres -D /var/lib/postgresql/11/main -c config_file=/etc/postgresql/11/main/postgresql.conf
postgres 31066 0.0 0.0 628896 6240 ? Ss 19:54 0:00 /usr/lib/postgresql/11/bin/postgres -D /var/lib/postgresql/11/main -c config_file=/etc/postgresql/11/main/postgresql.conf
postgres 31067 0.0 0.0 628896 6240 ? Ss 19:54 0:00 /usr/lib/postgresql/11/bin/postgres -D /var/lib/postgresql/11/main -c config_file=/etc/postgresql/11/main/postgresql.conf
postgres 31068 0.0 0.0 628896 6240 ? Rs 19:54 0:00 /usr/lib/postgresql/11/bin/postgres -D /var/lib/postgresql/11/main -c config_file=/etc/postgresql/11/main/postgresql.conf
Hors ligne
Pour répondre à la question précédente, PostgreSQL n'accepte plus les connexions dès la demande d'arrêt. Le message "FATAL: le système de base de données s'arrête" indique que PostgreSQL a reçu une demande de connexion qu'il a refusé. Au sujet de ce message d'ailleurs, configurer vos traces en anglais serait une excellente idée. Voir le paramètre lc_messages pour ça.
Pour la liste des processus, est-il possible d'avoir le résultat d'un "ps -ef | grep postgres" ? là, on a a priori que le PID et pas le PPID. Et j'avoue que j'ai un poil d'inquiétude sur tous les /usr/lib/postgresql/11/bin/postgres. Avoir le PPID serait très intéressant.
Guillaume.
Hors ligne
Ok il est arrêté. Donc : 30 minutes pour s'arrêter.
2021-10-29 20:05:50.268 GMT [26440] logrepli@ppv FATAL: le système de base de données s'arrête
2021-10-29 20:05:50.268 GMT [26438] logrepli@ppv FATAL: le système de base de données s'arrête
2021-10-29 20:05:50.305 GMT [1809] LOG: le système de base de données est arrêté
@Guillaume : Je relance re-stoppe et fait le ps -ef.
Merci pour la suggestion.
Hors ligne
@Guillaume :
root@lin01:~# ps -ef |grep postgres
root 838 1773 0 20:12 pts/0 00:00:00 grep postgres
postgres 27165 1 2 20:10 ? 00:00:02 /usr/lib/postgresql/11/bin/postgres -D /var/lib/postgresql/11/main -c config_file=/etc/postgresql/11/main/postgresql.conf
postgres 29215 27165 1 20:10 ? 00:00:00 postgres: 11/main: checkpointer
postgres 29219 27165 0 20:10 ? 00:00:00 postgres: 11/main: stats collector
root 29516 29514 0 20:11 pts/1 00:00:00 systemctl stop postgresql@11-main
postgres 29518 1 0 20:11 ? 00:00:00 /usr/bin/perl -wT /usr/bin/pg_ctlcluster --skip-systemctl-redirect -m fast 11-main stop
postgres 29520 29518 0 20:11 ? 00:00:00 /usr/lib/postgresql/11/bin/pg_ctl stop -s -w -D /var/lib/postgresql/11/main -m fast
root@lin01:~#
Hors ligne
ET toujours :
2021-10-29 20:14:22.829 GMT [12477] logrepli@ppv FATAL: le système de base de données s'arrête
2021-10-29 20:14:22.852 GMT [12478] logrepli@ppv FATAL: le système de base de données s'arrête
2021-10-29 20:14:22.853 GMT [12479] logrepli@ppv FATAL: le système de base de données s'arrête
2021-10-29 20:14:22.869 GMT [12480] logrepli@ppv FATAL: le système de base de données s'arrête
etc...
Hors ligne
Il devrait s'arrêter rapidement là. IL n'y a aucun processus qui peut l'arrêter à ce moment. Je ne vois pas pourquoi il conserve son checkpointer et son stats collector.
Guillaume.
Hors ligne
Ah, par contre, une raison pour laquelle il n'arriverait pas à s'arrêter est qu'il serait bombarder de demandes de connexion, qu'il passe son temps à refuser. Vous n'auriez pas un pooler qui cherche à se connecter avec un brin d'agressivité ? 
Guillaume.
Hors ligne
@Guillume : Si, si j'ai 5 serveurs synchronisés avec des souscriptions sur 53 tables.
Donc : 265 tables qui cherchent à se connecter aux abonnements ...
Est-ce une piste ?
Hors ligne
Vous avez une connexion par souscription. Ça m'étonnerait que vous ayez 256 souscriptions. Mais de toute façon, ça n'expliquerait pas cette quantité si importante de demande de connexions. Pour le confirmer ou l'infirmer, il faudrait regarder les logs des 5 serveurs synchronisés.
Guillaume.
Hors ligne
ok je regarde
Hors ligne
Et un autre test serait de stopper les cinq serveurs, puis de tenter l'arrêt en mode fast. Juste pour voir s'il s'arrête immédiatement (auquel cas les 5 serveurs sont fautifs) ou s'il met toujours du temps et s'il y a toujours ces traces.
Guillaume.
Hors ligne
sur un serveur distant :
2021-10-29 20:25:37.863 GMT [652] LOG: processus en tâche de fond « logical replication worker » (PID 28741) quitte avec le code de sortie 1
2021-10-29 20:25:37.863 GMT [28735] ERREUR: n'a pas pu se connecter au publieur : FATAL: le système de base de données s'arrête
FATAL: le système de base de données s'arrête
2021-10-29 20:25:37.863 GMT [28742] ERREUR: n'a pas pu se connecter au publieur : FATAL: le système de base de données s'arrête
FATAL: le système de base de données s'arrête
2021-10-29 20:25:37.863 GMT [28743] ERREUR: n'a pas pu se connecter au publieur : FATAL: le système de base de données s'arrête
FATAL: le système de base de données s'arrête
2021-10-29 20:25:37.863 GMT [28740] ERREUR: n'a pas pu se connecter au publieur : FATAL: le système de base de données s'arrête
FATAL: le système de base de données s'arrête
Hors ligne
sur tous en fait :
2021-10-29 20:27:08.462 GMT [2151] ERREUR: n'a pas pu se connecter au publieur : FATAL: le système de base de données s'arrête
FATAL: le système de base de données s'arrête
2021-10-29 20:27:08.465 GMT [623] LOG: processus en tâche de fond « logical replication worker » (PID 2150) quitte avec le code de sortie 1
2021-10-29 20:27:08.465 GMT [623] LOG: processus en tâche de fond « logical replication worker » (PID 2151) quitte avec le code de sortie 1
2021-10-29 20:27:08.465 GMT [623] LOG: processus en tâche de fond « logical replication worker » (PID 2149) quitte avec le code de sortie 1
2021-10-29 20:27:08.467 GMT [2152] ERREUR: n'a pas pu se connecter au publieur : FATAL: le système de base de données s'arrête
FATAL: le système de base de données s'arrête
2021-10-29 20:27:08.468 GMT [2153] ERREUR: n'a pas pu se connecter au publieur : FATAL: le système de base de données s'arrête
FATAL: le système de base de données s'arrête
2021-10-29 20:27:08.470 GMT [623] LOG: processus en tâche de fond « logical replication worker » (PID 2152) quitte avec le code de sortie 1
2021-10-29 20:27:08.471 GMT [623] LOG: processus en tâche de fond « logical replication worker » (PID 2153) quitte avec le code de sortie 1
Hors ligne
