Contexte
Le but de cet article n’est pas de détailler les différents modes de verrouillage et d’isolation des objets (se référer à la doc officielle Postgresql pour cela).
L’objectif, ici, est de détecter et d’analyser efficacement les sessions bloquées qui sont en attente de libération d’un verrou posé par une autre session, lors d’une transaction en cours. Quelle session est bloquée ? Sur quel objet ? Quelle est la session bloquante ? Depuis combien de temps ?
Ce problème est trop souvent sous-estimé dans le tuning sous Postgresql ou dans la supervision car, dans la majorité des situations, les locks ne sont pas (ou mal) détectés, la supervision ne remonte aucun problème de performance lié à une surconsommation des ressources du serveur (mémoire, CPU, disque).
De ce fait, bien souvent, on n’arrive pas à comprendre pourquoi, dans certains cas, une requête peut être longue et prendre 1 heure de plus qu’habituellement car elle a perdu du temps à attendre la libération d’un verrou.
Postgresql est en autocommit implicite, mais il est fréquent qu’une application utilise explicitement des transactions afin de garantir la cohérence de ses données. C’est précisément ce mécanisme de transaction qui, dans certains cas, peut entraîner des verrous dans une base Postgresql.
Symptômes
L’apparition d’un lock bloquant se manifeste souvent par les symptômes suivants :
- Une requête, habituellement rapide ou instantanée, paraît soudainement longue et interminable, sans raison apparente ;
- Aucune charge particulière n’est constatée sur l’instance Postgresql ou le serveur ;
- Le process Unix, correspondant à la session qui exécute la requête, ne consomme pas de CPU ;
- Facultatif : un ou plusieurs process Unix rattachés à Postgresql, ont un statut « idle in transaction ».
La vue pg_locks, native dans Postgresql, est malheureusement très limitée et ne fournit pas toujours les informations qui permettraient de comprendre quelle autre session est responsable du lock, et surtout sur quel objet.
Détection d’un verrou simple
Exemple d’une session bloquée car elle attend qu’une autre session termine sa transaction et libère le verrou.
base_test=# CREATE SCHEMA schema_test;
CREATE SCHEMA
base_test=# CREATE TABLE schema_test.employes (prenom VARCHAR(50), salaire NUMERIC);
CREATE TABLE
base_test=# INSERT INTO schema_test.employes VALUES ('Michel',1500);
INSERT 0 1
Session 1 : on ouvre une session et on démarre une transaction pour modifier le salaire de Michel, mais sans fermer la transaction (sans COMMIT ni ROLLBACK) :
base_test=# BEGIN; BEGIN base_test=# UPDATE schema_test.employes SET salaire = 1600 WHERE prenom = 'Michel'; UPDATE 1
Le process Unix correspondant à la session 1 affiche le statut « idle in transaction » :
[postgres@mon_serveur]$ ps -ef | grep "idle in transaction" | grep -v grep postgres 23596 1625 0 14:43 ? 00:00:00 postgres: postgres base_test [local] idle in transaction
Ce problème peut arriver lorsqu’une application ferme mal ses transactions et/ou sessions en cours, et des verrous restent sur les objets Postgresql.
Session 2 : on ouvre une autre session et on démarre une transaction pour modifier le salaire de Michel à une autre valeur que la précédente :
base_test=# BEGIN; BEGIN base_test=# UPDATE schema_test.employes SET salaire = 2000 WHERE prenom = 'Michel';
L’update ne rend pas la main : la session 2 est bloquée car elle attend que la session 1 libère le lock posé sur la ligne, dans la table schema_test.employes.
Tant que la session 1 n’a pas fait de commit, rollback, ou n’a pas été killée, la session 2 reste bloquée.
Le process Unix correspondant à la session 2 affiche le statut « UPDATE waiting ».
[postgres@mon_serveur]$ ps -ef | grep "waiting" | grep -v grep postgres 23776 1625 0 14:44 ? 00:00:00 postgres: postgres base_test [local] UPDATE waiting
Postgresql fournit nativement la vue pg_locks, qui permet de lister les verrous posés sur les objets, et de voir si les sessions ont bien accès aux objets ou si elles sont en attente.
postgres=# SELECT * FROM pg_locks; locktype | database | relation | page | tuple | virtualxid | transactionid | classid | objid | objsubid | virtualtransaction | pid | mode | granted | fastpath --------------+----------+----------+------+-------+------------+---------------+---------+-------+----------+--------------------+-------+-------------------------+---------+---------- relation | 189239 | 11695 | null | null | null | null | null | null | null | 5/1283998 | 24847 | AccessShareLock | t | t virtualxid | null | null | null | null | 5/1283998 | null | null | null | null | 5/1283998 | 24847 | ExclusiveLock | t | t relation | 189239 | 189501 | null | null | null | null | null | null | null | 4/1291735 | 23776 | RowExclusiveLock | t | t virtualxid | null | null | null | null | 4/1291735 | null | null | null | null | 4/1291735 | 23776 | ExclusiveLock | t | t relation | 189239 | 189501 | null | null | null | null | null | null | null | 3/887688 | 23596 | RowExclusiveLock | t | t virtualxid | null | null | null | null | 3/887688 | null | null | null | null | 3/887688 | 23596 | ExclusiveLock | t | t relation | 16706 | 18729 | null | null | null | null | null | null | null | 2/156124 | 24594 | AccessShareLock | t | t virtualxid | null | null | null | null | 2/156124 | null | null | null | null | 2/156124 | 24594 | ExclusiveLock | t | t relation | 16706 | 18649 | null | null | null | null | null | null | null | 2/156124 | 24594 | ShareUpdateExclusiveLock| t | f transactionid | null | null | null | null | null | 53086065 | null | null | null | 4/1291735 | 23776 | ShareLock | f | f tuple | 189239 | 189501 | 0 | 4 | null | null | null | null | null | 4/1291735 | 23776 | ExclusiveLock | t | f transactionid | null | null | null | null | null | 53111063 | null | null | null | 4/1291735 | 23776 | ExclusiveLock | t | f transactionid | null | null | null | null | null | 53086065 | null | null | null | 3/887688 | 23596 | ExclusiveLock | t | f
En filtrant sur la colonne « granted IS false », on peut récupérer le PID Unix de la session bloquée :
postgres=# SELECT * FROM pg_locks WHERE granted IS false; locktype | database | relation | page | tuple | virtualxid | transactionid | classid | objid | objsubid | virtualtransaction | pid | mode | granted | fastpath --------------+----------+----------+------+-------+------------+---------------+---------+-------+----------+--------------------+-------+-----------+---------+---------- transactionid | null | null | null | null | null | 53086065 | null | null | null | 4/1291735 | 23776 | ShareLock | f | f
On retrouve bien, dans cet exemple, le PID 23776, qui correspond au process Unix au statut « UPDATE waiting » repéré précédemment.
Néanmoins, le résultat de cette vue n’est pas très parlant car, à part faire un kill de la session bloquante, on ne peut pas récupérer facilement les informations sur la session bloquante, la session bloquée, l’objet sur lequel le lock est posé… Et donc le cas risque de se reproduire si l’on n’a pas compris ni corrigé l’origine du problème.
C’est là qu’intervient la requête magique, qui permet de récupérer d’un seul coup toutes les informations sur :
- La session bloquante (PID, user Postgresql, hostname ou adresse IP, dernière requête SQL lancée, heure de début de la session, heure de début de la requête bloquante) ;
- La session bloquée (PID, user Postgresql, hostname ou adresse IP, dernière requête SQL lancée, heure de début de la session, heure de début de la requête bloquée) ;
- La durée depuis laquelle la session bloquée est en attente ;
- Les informations sur l’objet verrouillé par la session bloquante, sur lequel le lock est posé : schéma de l’objet, nom de l’objet, type d’objet (table, index, séquence, vue).
Attention : la requête est à lancer, dans une autre session, sur la base concernée (« base_test » dans l’exemple). En effet, la vue pg_class, qui permet d’avoir les informations sur l’objet locké, est spécifique à chaque base. Ainsi, la requête ci-dessous ne renverrait aucun résultat si on la lançait sur une autre base de l’instance, où aucun lock se serait présent.
Il est conseillé d’activer l’affichage étendu (« \x ») si elle est lancée sous psql en mode console, pour une meilleure visibilité du résultat
base_test=# \x
Expanded display is on.
SELECT
nom_base,
schema_objet_locke,
nom_objet_locke,
type_objet_locke,
duree_bloquage,
pid_session_bloquante,
user_session_bloquante,
client_session_bloquante,
derniere_requete_session_bloquante,
heure_debut_session_bloquante,
heure_debut_requete_bloquante,
pid_session_bloquee,
user_session_bloquee,
client_session_bloquee,
derniere_requete_session_bloquee,
heure_debut_requete_bloquee,
heure_debut_session_bloquee
FROM
(
SELECT distinct
RANK() OVER (PARTITION BY c.pid ORDER BY g.query_start DESC) as rang,
c.datname AS nom_base,
e.nspname AS schema_objet_locke,
d.relname AS nom_objet_locke,
CASE
WHEN d.relkind IN ('t','r') THEN 'table'
WHEN d.relkind = 'i' THEN 'index'
WHEN d.relkind = 's' THEN 'sequence'
WHEN d.relkind = 'v' THEN 'vue'
ELSE d.relkind::text
END AS type_objet_locke,
TO_CHAR(now()-c.query_start,'DD')||'j '||TO_CHAR(now()-c.query_start,'HH24:MI:SS') AS duree_bloquage,
g.pid AS pid_session_bloquante,
g.usename AS user_session_bloquante,
g.client_addr AS client_session_bloquante,
g.query AS derniere_requete_session_bloquante,
TO_CHAR(g.backend_start,'YYYYMMDD HH24:MI:SS') AS heure_debut_session_bloquante,
TO_CHAR(g.query_start,'YYYYMMDD HH24:MI:SS') AS heure_debut_requete_bloquante,
c.pid AS pid_session_bloquee,
c.usename AS user_session_bloquee,
c.client_addr AS client_session_bloquee,
c.query AS derniere_requete_session_bloquee,
TO_CHAR(c.query_start,'YYYYMMDD HH24:MI:SS') AS heure_debut_requete_bloquee,
TO_CHAR(c.backend_start,'YYYYMMDD HH24:MI:SS') AS heure_debut_session_bloquee
FROM
pg_locks AS a,
pg_locks AS b,
pg_stat_activity AS c,
pg_class AS d,
pg_namespace AS e,
pg_locks AS f,
pg_stat_activity AS g
WHERE a.pid = b.pid
AND a.pid = c.pid
AND b.relation = d.oid
AND d.relnamespace = e.oid
AND b.relation = f.relation
AND b.pid <> f.pid
AND f.pid = g.pid
AND c.query_start >= g.query_start
AND a.granted IS FALSE
AND b.relation::regclass IS NOT NULL
AND e.nspname NOT IN ('pg_catalog','pg_toast','information_schema')
AND e.nspname NOT LIKE 'pg_temp_%'
AND f.granted is true
) AS resultat
WHERE rang = 1
ORDER BY resultat.heure_debut_requete_bloquee,resultat.heure_debut_requete_bloquante ;
-[ RECORD 1 ]----------------------+------------------------------------------------------------------------
nom_base | base_test
schema_objet_locke | schema_test
nom_objet_locke | employes
type_objet_locke | table
duree_bloquage | 00j 00:04:01
pid_session_bloquante | 23596
user_session_bloquante | postgres
client_session_bloquante | null
derniere_requete_session_bloquante | UPDATE schema_test.employes SET salaire = 1600 WHERE prenom = 'Michel';
heure_debut_session_bloquante | 20181002 14:43:40
heure_debut_requete_bloquante | 20181002 14:43:44
pid_session_bloquee | 23776
user_session_bloquee | postgres
client_session_bloquee | null
derniere_requete_session_bloquee | UPDATE schema_test.employes SET salaire = 2000 WHERE prenom = 'Michel';
heure_debut_requete_bloquee | 20181002 14:44:20
heure_debut_session_bloquee | 20181002 14:44:12
On a ainsi toutes les informations nécessaires pour corriger le problème et éviter que la situation ne se reproduise à l’avenir. On peut ainsi :
- Soit killer la session bloquante (PID 23596) si, pour une raison quelconque, la transaction ne s’est pas terminée ou est toujours en cours d’exécution ;
- Soit corriger le traitement qui lance la session bloquante, afin de terminer proprement la transaction ou d’optimiser la durée d’exécution ;
- Soit modifier la planification des 2 traitements pour qu’ils n’essaient plus de modifier simultanément les mêmes lignes d’une table (row-level lock).
Remarque : cet exemple montre le cas où, volontairement, une transaction est inactive et pas terminée. Mais la requête fonctionne aussi pour les transactions en cours (exemple : un UPDATE très long d’une session, qui pourrait mettre en attente la modification des mêmes lignes par une autre session).
Détection d’un verrou en cascade
Cas plus complexe où plusieurs sessions sont bloquées en cascade, pour détecter la session « mère » à l’origine du blocage initial
base_test=# CREATE SCHEMA schema_test;
CREATE SCHEMA
base_test=# CREATE TABLE schema_test.employes (prenom VARCHAR(50), salaire NUMERIC);
CREATE TABLE
base_test=# INSERT INTO schema_test.employes VALUES ('Michel',1500);
INSERT 0 1
base_test=# CREATE TABLE schema_test.agences (ville VARCHAR(50), code NUMERIC);
CREATE TABLE
base_test=# INSERT INTO schema_test.agences VALUES ('Paris',1);
INSERT 0 1
Session 1 : on ouvre une session et on démarre une transaction pour modifier le salaire de Michel, mais sans fermer la transaction (sans COMMIT ni ROLLBACK) :
base_test=# BEGIN; BEGIN base_test=# UPDATE schema_test.employes SET salaire = 1600 WHERE prenom = 'Michel'; UPDATE 1
Session 2 : on ouvre une autre session et on démarre une transaction pour modifier le code de l’agence de Paris dans la table « agences », puis le salaire de Michel, le tout dans la même transaction :
base_test=# BEGIN; BEGIN base_test=# UPDATE schema_test.agences SET code = 2 WHERE ville = 'Paris' ; UPDATE 1 base_test=# UPDATE schema_test.employes SET salaire = 2000 WHERE prenom = 'Michel';
L’update de la table « agences » a abouti, mais la transaction reste bloquée sur l’update de la table employes, comme dans le cas précédent
Session 3 : on ouvre une autre session et on démarre une transaction pour modifier le code de l’agence de Paris dans la table « agences » :
base_test=# BEGIN; BEGIN base_test=# UPDATE schema_test.agences SET code = 3 WHERE ville = 'Paris' ;
Bilan de la situation :
- la session 3 est bloquée par la session 2 (lock sur la ligne ville=’Paris’ dans la table « agences »)
- la session 2 est bloquée par la session 1 (lock sur la ligne prenom=’Michel’ dans la table « employes »)
On lance, dans une autre session, la même requête que précédemment et on observe le résultat :
base_test=# \x
Expanded display is on.
SELECT
nom_base,
schema_objet_locke,
nom_objet_locke,
type_objet_locke,
duree_bloquage,
pid_session_bloquante,
user_session_bloquante,
client_session_bloquante,
derniere_requete_session_bloquante,
heure_debut_session_bloquante,
heure_debut_requete_bloquante,
pid_session_bloquee,
user_session_bloquee,
client_session_bloquee,
derniere_requete_session_bloquee,
heure_debut_requete_bloquee,
heure_debut_session_bloquee
FROM
(
SELECT distinct
RANK() OVER (PARTITION BY c.pid ORDER BY g.query_start DESC) as rang,
c.datname AS nom_base,
e.nspname AS schema_objet_locke,
d.relname AS nom_objet_locke,
CASE
WHEN d.relkind IN ('t','r') THEN 'table'
WHEN d.relkind = 'i' THEN 'index'
WHEN d.relkind = 's' THEN 'sequence'
WHEN d.relkind = 'v' THEN 'vue'
ELSE d.relkind::text
END AS type_objet_locke,
TO_CHAR(now()-c.query_start,'DD')||'j '||TO_CHAR(now()-c.query_start,'HH24:MI:SS') AS duree_bloquage,
g.pid AS pid_session_bloquante,
g.usename AS user_session_bloquante,
g.client_addr AS client_session_bloquante,
g.query AS derniere_requete_session_bloquante,
TO_CHAR(g.backend_start,'YYYYMMDD HH24:MI:SS') AS heure_debut_session_bloquante,
TO_CHAR(g.query_start,'YYYYMMDD HH24:MI:SS') AS heure_debut_requete_bloquante,
c.pid AS pid_session_bloquee,
c.usename AS user_session_bloquee,
c.client_addr AS client_session_bloquee,
c.query AS derniere_requete_session_bloquee,
TO_CHAR(c.query_start,'YYYYMMDD HH24:MI:SS') AS heure_debut_requete_bloquee,
TO_CHAR(c.backend_start,'YYYYMMDD HH24:MI:SS') AS heure_debut_session_bloquee
FROM
pg_locks AS a,
pg_locks AS b,
pg_stat_activity AS c,
pg_class AS d,
pg_namespace AS e,
pg_locks AS f,
pg_stat_activity AS g
WHERE a.pid = b.pid
AND a.pid = c.pid
AND b.relation = d.oid
AND d.relnamespace = e.oid
AND b.relation = f.relation
AND b.pid <> f.pid
AND f.pid = g.pid
AND c.query_start >= g.query_start
AND a.granted IS FALSE
AND b.relation::regclass IS NOT NULL
AND e.nspname NOT IN ('pg_catalog','pg_toast','information_schema')
AND e.nspname NOT LIKE 'pg_temp_%'
AND f.granted is true
) AS resultat
WHERE rang = 1
ORDER BY resultat.heure_debut_requete_bloquee,resultat.heure_debut_requete_bloquante ;
-[ RECORD 1 ]----------------------+------------------------------------------------------------------------
nom_base | base_test
schema_objet_locke | schema_test
nom_objet_locke | employes
type_objet_locke | table
duree_bloquage | 00j 00:23:46
pid_session_bloquante | 22212
user_session_bloquante | postgres
client_session_bloquante | null
derniere_requete_session_bloquante | UPDATE schema_test.employes SET salaire = 1600 WHERE prenom = 'Michel';
heure_debut_session_bloquante | 20181002 11:29:44
heure_debut_requete_bloquante | 20181002 14:16:07
pid_session_bloquee | 14736
user_session_bloquee | postgres
client_session_bloquee | null
derniere_requete_session_bloquee | UPDATE schema_test.employes SET salaire = 2000 WHERE prenom = 'Michel';
heure_debut_requete_bloquee | 20181002 14:17:16
heure_debut_session_bloquee | 20181002 14:16:59
-[ RECORD 2 ]----------------------+------------------------------------------------------------------------
nom_base | base_test
schema_objet_locke | schema_test
nom_objet_locke | agences
type_objet_locke | table
duree_bloquage | 00j 00:21:41
pid_session_bloquante | 14736
user_session_bloquante | postgres
client_session_bloquante | null
derniere_requete_session_bloquante | UPDATE schema_test.employes SET salaire = 2000 WHERE prenom = 'Michel';
heure_debut_session_bloquante | 20181002 14:16:59
heure_debut_requete_bloquante | 20181002 14:17:16
pid_session_bloquee | 15415
user_session_bloquee | postgres
client_session_bloquee | null
derniere_requete_session_bloquee | UPDATE schema_test.agences SET code = 3 WHERE ville = 'Paris' ;
heure_debut_requete_bloquee | 20181002 14:19:21
heure_debut_session_bloquee | 20181002 14:19:07
La session avec le PID 22212 bloque la session avec le PID 14736
La session avec le PID 14736 bloque la session avec le PID 15415
Dans le cas de blocages en cascade, le premier enregistrement retourné par la requête renvoie les informations sur la session à l’origine du blocage en cascade (la première dans la hiérarchie)
Conclusion
Afin de superviser intelligemment les locks, il est conseillé de faire un script qui boucle sur l’ensemble des bases de l’instance (vue pg_database), et d’exécuter régulièrement cette requête sur chacune des bases.
Si la requête renvoie au moins une ligne, c’est qu’au moins une session est bloquée par une autre, en attente de libération d’un verrou, et c’est toujours intéressant de le remonter dans la supervision car les locks peuvent parfois être à l’origine de problèmes de performances