Vous n'êtes pas identifié(e).
Bonjour à tous,
Nous utilisons postgresql 9.4 sur un environnement linux, et nous constatons qu'il arrive dés fois, environ 1,2,5 fois par jour un embouteillage soudaine des requêtes sur le serveur. Cela se produit durant 10 minutes ou 15 minutes, les requêtes deviennent aussitôt lentes (si par exemple la requête s’exécute en 1 seconde normalement elle se fige et ne se termine pas durant ce temps) tout à coup et ne se termine pas durant cette durée, aussi les requêtes commencent alors à s'accumuler durant cette période et la charge du serveur qui pourrait commencer à s'augmenter également au niveau des CPU. Puis après attente, on constate que l'embouteillage est fini, et les requêtes se finissent soudainement et reprend son durée d’exécution normales.
Je tiens à remarquer qu'il n'y a pas blocage entre les requêtes, ou sinon seulement 4 ou 7 requêtes bloquantes sur 65 requêtes qui s'accumulent. Le blocage ne s'apparait qu'après, ie que vu que les requêtes s'accumulent entre elles, viennent alors ensuite quelques blocages mais qui je pense ne sont pas la cause mais l'effet de cet embouteillage soudain vraiment gênant. J'utilise le mot embouteillage vu que je ne trouve pas d'autres termes jusqu'à présent pour expliquer le problème, peut être un freeze? Durant la lenteur, même si j'annule les autovaccum, l'embouteillage ne se termine pas toujours.
Pour plus d'information nous utilisons également tomcat pour servir de serveur web applicatif, seulement là aussi je ne pense pas que le problème pourrait y venir.
Sauriez vous la cause de ce problème, car la situation devient assez gênante. Avez vous des solutions à proposer ?
Merci de votre attention à ce sujet 
Hors ligne
Sans plus d'information, impossible de vous aider.
Que disent les métriques sytèmes et postgres quand le problème survient ? Ou y a-t-il des messages dans les logs ?
Julien.
https://rjuju.github.io/
Hors ligne
Qu'entendez vous par métriques systèmes et postgres ?
En ce qui concerne les log postgres, il y a pas trop de piste, seulement des messages du genre :
LOG: process 52694 still waiting for ShareLock on transaction 53543073 after 8000.051 ms
DETAIL: Process holding the lock: 52320. Wait queue: 52694.
CONTEXT: while locking tuple (558553,3) in relation "object_item"
Ce qui est assez normale vu que, les requêtes sont en fil d'attentes.
Et sinon les logs figurent aussi des messages du genre:
LOG: process 52839 acquired AccessExclusiveLock on tuple (558590,3) of relation 7539547 of database 16384 after 642909.003 ms
CONTEXT: SQL statement "SELECT id FROM numenvault.Object_item WHERE id = $1 FOR UPDATE"
>>> Ici, les requêtes retournent à leur temps d'execution normale
Sinon, à part çà les logs ne montrent pas grand chose, seulement les durées d’exécution de requêtes et les logs de connections et de déconnections.
>>>>> Ce qui m'étonne c'est que qu'est ce qui fait que la durée d’exécution des requêtes augmentent elles tout d'un coup, passage d'1seconde en 10 minutes soudainement et revient à la normale après? C'est comme si le planner a changé de chemin ou je ne sais pas ?
Est ce que ceci y ait déjà survenu chez vous, avez vous une avis sur le sujet ?
Je tiens toutefois à signaler que la taille des bases de données dont je parle ici atteigne les 400Go ou plus.
Hors ligne
En utilisant des SELECT FOR UPDATE, vous demandez à PostgreSQL de verrouiller les lignes renvoyées par le SELECT. Si jamais deux processus essaient de verrouiller une ou plusieurs mêmes lignes, le premier processus obtient le verrou et le deuxième est bloqué derrière en attendant que le premier libère son verrou (donc quand il termine sa transaction). Si jamais ce premier processus met du temps à terminer sa transaction, alors le risque qu'un autre processus se retrouve bloqué est plus important et la durée de ce blocage sera lui-aussi plus important. Si vous utilisez SELECT FOR UPDATE, vous devez vous assurer que les transactions générant ces verrous soient les plus rapides possibles pour éviter ce type de contentions. Mais bon, du coup, le problème là n'est pas du côté de PostgreSQL ou de sa configuration. Il est du côté de l'applicatif.
Guillaume.
Hors ligne
Bien vu, et merci pour cette réponse, là je suis d'accord. Ce qui m'étonne toute fois, c'est que les durées d'attentes sont de 10 minutes ou plus, alors que la requête utilisant SELECT FOR UPDATE elle met 1 à 2sec en moyenne à s’exécuter. Par ailleurs, j'ai eu la chance d'avoir pu visualiser le phénomène hier sur l'état du serveur dans pgAdmin. La requête s’exécute et ne se termine pas au moment prévu, son temps d’exécution augmente, puis viens une autre requête avec la même situation, et puis une autre et ainsi de suite.. Pourtant, après vérification il n'existe pas de blocage entre ces requêtes donc je suppose qu'ici il n'y a pas d'attente de verrou non ? Et pourtant c'est requêtes s'accumulant qui normalement met 1 ou 2 sec à s’exécuter ne se terminent qu'après 10 min ou plus, elles se terminent tous à peu près en même temps après mais toute fois avec 1 sec d’écart à peu près.
Est ce toujours un problème de verrou ou d'où pourrait provenir le problème? Est ce que par hasard il y aurait il une liaison avec les ecritures checkpoint, un paramétrage peut être mal configuré, on a checkpoint_segments = 64 avec checkpoint_completion_target = 0.8 ?
Bien à vous
Hors ligne
Après avoir revérifier les logs, il s'agit surement de problème de verrou.
Mais ce qui m'étonne toujours c'est que pourquoi existe il cette attente de verrou, pourquoi la durée d'execution de la requête détentive du verrou vire t elle de 1 sec à 10 minutes ?
Hors ligne
Bonjour, je relève le sujet car je pense que les attentes sur les verrous sont des conséquences mais pas de causes.. Puisque ces attentes n'apparaissent qu'à 3/4 fois par jour (ennuyant bien sur), mais ces attentes sont dus je pense à une variation soudaine de la durée d’exécution des requêtes:
- Soit à cause du chemin du planner qui à changer ?
- Soit à cause du charge du serveur énorme.
Mais pourquoi ???
Car en effet, la base est installée dans une instance. Or sur le serveur physique (128Go de RAM) il y existe 3 instances qui elles aussi conservent des dizaines/ vingtaines de base de données (certaines de grande tailles > 200Go, et d'autres petites). Ce qui me laisse à penser que peut être le serveur n'arrive pas à suivre les demandes. Que les instances se bouffent les ressources entre elles peut être? Ce qui va entrainer une réservation de cache par d'autres instances, qui pénaliseront les autres instances surtout les grandes bases, et qui va ensuite entrainer la lenteur de la requête , non ???
Est ce que vous pensez que cette théorie est plausible ? Une remarque toute fois, c'est surtout les grandes bases qui subissent ces lenteurs soudaines de requêtes et après genre 5minutes, les requêtes reprennent son rythme d'execution normale !!!
Pour les logs, rien d'incroyable, mis à part les logs style attentes/acquisition de verrous suite à un laps de temps.. ce qui je pense n'étant pas la cause mais la conséquence ici , non ???
Svp, merci de porter votre attention sur ce sujet , car je ne trouve pas d'autres explications alors que le problème est assez énervant et devrait être résolu, alors comptant sur vos soutiens et idées pour aider
Hors ligne
Avant de pouvoir dire quoi que ce soit, il serait bon d'avoir quelques métriques systèmes pour savoir d'où vient le goulet d'étranglement. Pensez à utiliser vmstat la prochaine fois que cela se produit, ça permettra d'en savoir plus.
Guillaume.
Hors ligne
Je n'ai pas encore eu l'occasion d'utiliser vmstat au moment du lenteur aujourd'hui. Sinon, si çà peut aider, le résultat d'un htop seront un peu pareil à comme ceci:
1 [||||||||||||||||||||||||||||||||||||||97.5%] 7 [||||||||||||||||||||||||||||||||||||||91.8%] 13 [||||||||||||||||||||||||||||||||||||||95.6%] 19 [||||||||||||||||||||||||||||||||||||||95.0%]
2 [||||||||||||||||||||||||||||||||||||||96.9%] 8 [||||||||||||||||||||||||||||||||||||||93.2%] 14 [||||||||||||||||||||||||||||||||||||||96.9%] 20 [||||||||||||||||||||||||||||||||||||||94.4%]
3 [||||||||||||||||||||||||||||||||||||||99.4%] 9 [||||||||||||||||||||||||||||||||||||||91.3%] 15 [||||||||||||||||||||||||||||||||||||||96.9%] 21 [||||||||||||||||||||||||||||||||||||||95.7%]
4 [||||||||||||||||||||||||||||||||||||||96.2%] 10 [||||||||||||||||||||||||||||||||||||||95.7%] 16 [||||||||||||||||||||||||||||||||||||||90.7%] 22 [||||||||||||||||||||||||||||||||||||||94.4%]
5 [||||||||||||||||||||||||||||||||||||||95.6%] 11 [||||||||||||||||||||||||||||||||||||||85.6%] 17 [||||||||||||||||||||||||||||||||||||||96.2%] 23 [||||||||||||||||||||||||||||||||||||||92.5%]
6 [||||||||||||||||||||||||||||||||||||||95.0%] 12 [||||||||||||||||||||||||||||||||||||||95.0%] 18 [||||||||||||||||||||||||||||||||||||||88.3%] 24 [||||||||||||||||||||||||||||||||||||||86.2%]
Mem[||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||30673/129190MB] Tasks: 755, 231 kthr; 32 running
Swp[|||||| 3416/61033MB] Load average: 52.17 55.64 46.91
Uptime: 74 days, 02:00:17
***********************
Par ailleurs, j'ai lancé un EXPLAIN(buffers,analyze) de la requête qui subissait une lenteur et effectivement j'ai vu que postgresql utilisée une partie de bloc de disque pour avoir les résultats. Comme ex: Buffers: shared hit=167859 read=14243 et bien sur , plus il utilisise de disque plus la durée d'execution de la requête est longue. Puis, une fois la requête executée elle revient à son temps d'execution normale avec une lecture seulement dans le cache cette fois ci, avec Buffers: shared hit=214390. Mais la vrai question est pourquoi la requête tout d'un coup à besoin de lire dans les blocs pour s'executer, ou est ce que c'est lié au concurrence entre les instances, que j'ai mentionné plus haut ?
Hors ligne
Tout ce que montre le htop, c'est que les CPU sont utilisés à 100%, ce qui laisserait entendre que le problème vient plus du CPU que des disques.
Guillaume.
Hors ligne
Salut,
Gleu> Oui les CPU sont largement utilisés quand il existe beaucoup de requêtes en lancement (en phase de production). Donc tu veux dire que le serveur (le CPU) est en surcharge ? Qu'il faudrait peut être migré quelque bases dans un autre serveur, ou quel action d'amélioration peux tu me conseiller ?
****
En fait entre parenthèse j'aimerai savoir si possible, analyze recolte les statistiques pour être utilisé par la suite par l'optimisateur de requête, aussi, est ce que "explain analyze" récolte aussi les statistiques ou lance t elle tout simplement la requête en affichant son parcours et ses coûts. En gros, est ce que explain analyze hérite elle aussi des mécanismes de la commande ANALYZE ?
Hors ligne
Quel système disque avez-vous sur le serveur, de combien de RAM disposez vous et quelles sont les paramètres de configuration que vous avez modifié ?
SELECT name, current_setting(name), source, sourcefile, sourceline FROM pg_settings WHERE (source <> 'default' OR name = 'server_version') AND name NOT IN ('config_file', 'data_directory', 'hba_file', 'ident_file');Pour répondre à votre question, EXPLAIN ANALYZE ne récolte pas de statistique. Cela exécute la requête (attention aux insert, delete et fonction en écriture, pensez à faire un begin / rollback), affiche le plan d'exécution avec les coûts estimés ainsi que les coûts réels.
Julien.
https://rjuju.github.io/
Hors ligne
- Disque ext4 partitionné en GPT
- RAM 128Go
Config postgres:
"application_name"-----"pgAdmin III - ??diteur de requ??tes"
"archive_command"-----"rsync -a %p postgres@fsd3.numen.mg:/part_2/db_replica/wal_archives/serv1-9.4.5/%f"
"archive_mode"-----"on"
"bytea_output"-----"escape"
"checkpoint_segments"-----"32"
"client_encoding"-----"UNICODE"
"client_min_messages"-----"notice"
"data_checksums"-----"off"
"DateStyle"-----"ISO, MDY"
"default_text_search_config"-----"pg_catalog.french"
"dynamic_shared_memory_type"-----"posix"
"effective_cache_size"-----"39GB"
"hot_standby"-----"on"
"huge_pages"-----"try"
"lc_collate"-----"fr_FR.UTF8"
"lc_ctype"-----"fr_FR.UTF8"
"lc_messages"-----"en_US"
"lc_monetary"-----"en_US"
"lc_numeric"-----"en_US"
"lc_time"-----"en_US"
"listen_addresses"-----"*"
"log_autovacuum_min_duration"-----"0"
"log_checkpoints"-----"on"
"log_connections"-----"on"
"log_destination"-----"stderr"
"log_directory"-----"/data01/PostgreSQL/9.4.5/pg_log/log_srvl1_5452"
"log_disconnections"-----"on"
"log_filename"-----"postgresql-%Y-%m-%d.log"
"log_line_prefix"-----"%t [P:%p][D:%d]: [%l-1] "
"log_lock_waits"-----"on"
"log_min_duration_statement"-----"500ms"
"log_rotation_age"-----"1d"
"log_rotation_size"-----"10MB"
"log_statement"-----"none"
"log_temp_files"-----"0"
"log_truncate_on_rotation"-----"off"
"logging_collector"-----"on"
"maintenance_work_mem"-----"7680MB"
"max_connections"-----"400"
"max_stack_depth"-----"2MB"
"max_wal_senders"-----"5"
"port"-----"5452"
"random_page_cost"-----"2"
"server_encoding"-----"UTF8"
"server_version"-----"9.4.5"
"shared_buffers"-----"15GB"
"TimeZone"-----"localtime"
"transaction_deferrable"-----"off"
"transaction_isolation"-----"read committed"
"transaction_read_only"-----"off"
"wal_buffers"-----"16MB"
"wal_keep_segments"-----"100"
"wal_level"-----"hot_standby"
"work_mem"-----"480MB"
Hors ligne