Dans chaque déploiement, il y a toujours quelques requêtes qui s'exécutent trop lentement.
Poursuivez votre lecture pour découvrir comment découvrir les requêtes qui prennent trop de temps à s'exécuter et comment comprendre pourquoi elles sont lentes.
Utiliser simplement pg_stat_statements ?
pg_stat_statements est une extension populaire incluse dans la distribution principale de PostgreSQL et disponible par défaut sur presque tous les fournisseurs DBaaS. C'est inestimable et c'est plus ou moins le seul moyen d'obtenir des statistiques sur les requêtes sans installer d'extensions personnalisées.
Il a cependant quelques limitations lorsqu'il s'agit de découvrir des requêtes lentes.
Statistiques cumulées
L'extension pg_stat_statements fournit des informations cumulatives statistiques sur chaque requête jamais exécutée par le serveur. Pour chaque requête, il affiche, entre autres mesures, le nombre total de fois où elle a été exécutée et le temps total pris pour toutes les exécutions.
Afin de "capturer" les requêtes lentes lorsqu'elles se produisent, vous devez récupérer périodiquement l'intégralité du contenu des pg_stat_statements visualisez-le, stockez-le dans une base de données de séries chronologiques et comparez le nombre d'exécutions. Par exemple, si vous avez le contenu de pg_stat_statements à 10h00 et 10h10, vous pouvez sélectionner les requêtes qui ont un nombre d'exécutions plus élevé à 10h10 qu'à 10h00. Pour ces requêtes, vous pouvez calculer le temps d'exécution moyen pendant cet intervalle, en utilisant :
(total time at 10.10 AM - total time at 10.00 AM) ÷ (total count at 10.10 AM - total count at 10.00 AM)
Si ce temps d'exécution moyen dépasse un seuil supérieur, vous pouvez déclencher une alerte pour agir.
Cela fonctionne raisonnablement bien dans la pratique, mais vous aurez besoin d'une bonne infrastructure de surveillance ou d'un service dédié comme pgDash.
Paramètres de la requête
pg_stat_statements ne capture pas les valeurs des paramètres de liaison passés aux requêtes.
L'une des choses que le planificateur de requêtes Postgres estime pour sélectionner un plan d'exécution est le nombre de lignes qu'une condition est susceptible de filtrer. Par exemple, si la plupart des lignes d'une table ont la valeur d'une colonne indexée pays comme "US", le planificateur peut décider de faire une analyse séquentielle de la table entière pour le où clause country = "US" , et peut décider d'utiliser une analyse d'index pour country = "UK" depuis le premier où La clause doit correspondre à la plupart des lignes de la table.
Connaître la valeur réelle des paramètres pour lesquels l'exécution de la requête a été lente peut aider à diagnostiquer plus rapidement les problèmes de requête lente.
Journalisation lente des requêtes
L'alternative la plus simple consiste à consigner les requêtes lentes. Contrairement à certains autres SGBD qui rendent cela facile, PostgreSQL nous présente un ensemble de paramètres de configuration similaires :
log_statementlog_min_duration_statementlog_min_duration_samplelog_statement_sample_ratelog_parameter_max_lengthlog_parameter_max_length_on_errorlog_duration
Celles-ci sont décrites en détail dans la documentation de Postgres. Voici un point de départ raisonnable :
# next line says only log queries that take longer 5 seconds
log_min_duration_statement = 5s
log_parameter_max_length = 1024
log_parameter_max_length_on_error = 1024
Ce qui se traduit par des journaux comme ceux-ci :
2022-04-14 06:17:11.462 UTC [369399] LOG: duration: 5.060 ms statement: select i.*, t."Name" as track, ar."Name" as artist
from "InvoiceLine" as i
join "Track" as t on i."TrackId" = t."TrackId"
join "Album" as al on al."AlbumId" = t."AlbumId"
join "Artist" as ar on ar."ArtistId" = al."ArtistId";
S'il y a trop de journaux, vous pouvez demander à Postgres de ne journaliser que (disons) 50 % des requêtes qui durent plus de 5 secondes :
log_min_duration_sample = 5s
log_statement_sample_rate = 0.5 # 0..1 => 0%..100%
Vous devriez bien sûr lire la documentation sur la signification et l'implication de ces paramètres avant de les ajouter à votre configuration Postgres. Soyez averti que les paramètres sont bizarres et non intuitifs.
Plans d'exécution des requêtes lentes
Il ne suffit généralement pas de savoir qu'une requête lente s'est produite, vous devrez également comprendre pourquoi c'était lent. Pour cela, vous vérifierez généralement d'abord le plan d'exécution de la requête.
auto_explain est une autre extension principale de PostgreSQL (également disponible sur la plupart des DBaaS) qui peut enregistrer les plans d'exécution des requêtes qui viennent de se terminer. Il est documenté ici.
Pour activer auto_explain, vous devez généralement l'ajouter à shared_preload_libraries et redémarrez Postgres. Voici un exemple de configuration de démarrage :
# logs execution plans of queries that take 10s or more to run
auto_explain.log_min_duration = 10s
auto_explain.log_verbose = on
auto_explain.log_settings = on
auto_explain.log_format = json
auto_explain.log_nested_statements = on
# enabling these provide more information, but have a performance cost
#auto_explain.log_analyze = on
#auto_explain.log_buffers = on
#auto_explain.log_wal = on
#auto_explain.log_timing = on
#auto_explain.log_triggers = on
Cela entraînera l'enregistrement des plans au format JSON, qui pourront ensuite être visualisés dans des outils comme ceux-ci.
Requêtes en cours d'exécution
Toutes les techniques répertoriées ci-dessus ont une chose en commun :elles produisent une sortie exploitable uniquement après une requête a terminé son exécution. Ils ne peuvent pas être utilisés pour gérer des requêtes qui sont si lentes cette fois-ci qu'elles n'ont pas encore terminé leur exécution.
Chaque connexion à un serveur PostgreSQL est gérée par un backend , en particulier un backend client . Lorsqu'un tel backend exécute une requête, son état est actif . Il peut également avoir démarré une transaction mais est ensuite inactif, appelé inactif dans la transaction état.
Le pg_stat_activity La vue système documentée ici fournit une liste de tous les backends Postgres en cours d'exécution. Vous pouvez interroger cette vue pour obtenir les requêtes en cours d'exécution :
SELECT client_addr, query_start, query
FROM pg_stat_activity
WHERE state IN ('active', 'idle in transaction')
AND backend_type = 'client backend';
D'ailleurs, sans utiliser d'extensions tierces, il n'y a aucun moyen de connaître le plan d'exécution d'une requête en cours d'exécution par un backend.
Verrous
Si le plan d'exécution d'une requête lente n'indique aucun problème évident, le backend exécutant la requête peut avoir été retardé par des verrous concurrents.
Les verrous sont obtenus explicitement ou implicitement lors de l'exécution de la requête pour diverses raisons. Un chapitre entier de la documentation de Postgres y est consacré.
Verrous de journalisation
En règle générale, une limite supérieure du temps d'attente est définie à l'aide de l'option lock_timeout , généralement côté client. Si une requête attend depuis si longtemps pour acquérir un verrou, Postgres annulera l'exécution de cette requête et consignera une erreur :
2021-01-30 09:35:52.415 UTC [67] psql postgres testdb 172.17.0.1 ERROR: canceling statement due to lock timeout
2021-01-30 09:35:52.415 UTC [67] psql postgres testdb 172.17.0.1 STATEMENT: cluster t;
Supposons que vous souhaitiez définir un délai d'attente de verrouillage de 1 minute, mais consigner les requêtes qui attendent des verrous pendant plus de, disons, 30 secondes. Vous pouvez le faire en utilisant :
log_lock_waits = on
deadlock_timeout = 30s
Cela créera des journaux comme celui-ci :
2021-01-30 09:49:22.331 UTC [70] psql postgres testdb 172.17.0.1 LOG: process 70 still waiting for ShareLock on transaction 493 after 30009.004 ms
2021-01-30 09:49:22.331 UTC [70] psql postgres testdb 172.17.0.1 DETAIL: Process holding the lock: 68. Wait queue: 70.
2021-01-30 09:49:22.331 UTC [70] psql postgres testdb 172.17.0.1 CONTEXT: while locking tuple (0,3) in relation "t"
2021-01-30 09:49:22.331 UTC [70] psql postgres testdb 172.17.0.1 STATEMENT: select * from t for update;
L'utilisation de deadlock_timeout n'est pas une faute de frappe :il s'agit de la valeur utilisée par le mécanisme de journalisation des attentes de verrouillage. Idéalement, il aurait dû y avoir quelque chose comme log_min_duration_lock_wait , mais malheureusement, ce n'est pas le cas.
En cas de blocages réels, Postgres abandonnera les transactions bloquées après deadlock_timeout durée, et enregistrera les déclarations incriminées. Aucune configuration explicite n'est nécessaire.
2021-01-30 09:55:37.724 UTC [68] psql postgres testdb 172.17.0.1 LOG: process 68 detected deadlock while waiting for ShareLock on transaction 496 after 30007.633 ms
2021-01-30 09:55:37.724 UTC [68] psql postgres testdb 172.17.0.1 DETAIL: Process holding the lock: 70. Wait queue: .
2021-01-30 09:55:37.724 UTC [68] psql postgres testdb 172.17.0.1 CONTEXT: while locking tuple (0,3) in relation "t"
2021-01-30 09:55:37.724 UTC [68] psql postgres testdb 172.17.0.1 STATEMENT: select * from t where a=4 for update;
2021-01-30 09:55:37.725 UTC [68] psql postgres testdb 172.17.0.1 ERROR: deadlock detected
2021-01-30 09:55:37.725 UTC [68] psql postgres testdb 172.17.0.1 DETAIL: Process 68 waits for ShareLock on transaction 496; blocked by process 70.
Process 70 waits for ShareLock on transaction 495; blocked by process 68.
Process 68: select * from t where a=4 for update;
Process 70: select * from t where a=0 for update;
2021-01-30 09:55:37.725 UTC [68] psql postgres testdb 172.17.0.1 HINT: See server log for query details.
2021-01-30 09:55:37.725 UTC [68] psql postgres testdb 172.17.0.1 CONTEXT: while locking tuple (0,3) in relation "t"
2021-01-30 09:55:37.725 UTC [68] psql postgres testdb 172.17.0.1 STATEMENT: select * from t where a=4 for update;
Découverte des verrous actuels
La liste complète des verrous actuellement accordés est disponible dans la vue système pg_locks. Cependant, il est généralement plus facile d'utiliser la fonction pg_blocking_pids , avec pg_stat_activity , comme ceci :
SELECT state, pid, pg_blocking_pids(pid), query
FROM pg_stat_activity
WHERE backend_type='client backend';
qui peut afficher une sortie comme celle-ci :
état state | pid | pg_blocking_pids | query
---------------------+--------+------------------+-------------------------------------------------
active | 378170 | {} | SELECT state, pid, pg_blocking_pids(pid), query+
| | | FROM pg_stat_activity +
| | | WHERE backend_type='client backend';
active | 369399 | {378068} | cluster "Track";
idle in transaction | 378068 | {} | select * from "Track" for update;
(3 rows)
qui indique qu'il y a un backend qui est bloqué (celui qui exécute l'instruction CLUSTER), et qu'il est bloqué par le PID 378068 (qui a exécuté un SELECT..FOR UPDATE mais est ensuite inactif dans la transaction).
