Traqueur : verrouillage

      Les verrous sont nécessaires sur un SGBDR et les blocages causés par le verrouillage (wait_event_type "Lock" dans pg_stat_activity) ne sont pas exactement des problèmes de performance. Cependant, un verrouillage inadapté provoquera pour les utilisateurs le même symptôme que les problèmes de performance classiques : le sablier.
      Le verrouillage excessif se traite sur le long terme au niveau de la logique applicative. Mais, pour débloquer rapidement des utilisateurs ou un traitement batch, il est nécessaire de savoir analyser la situation, voire de tuer certaines sessions etc.
      Simulation d’une situation de blocage avec PostgreSQL 10 beta :

select version(); version ----------------------------------------------------------------------------------------------------- PostgreSQL 10beta1 on x86_64-pc-linux-gnu, compiled by gcc (Debian 6.3.0-19) 6.3.0 20170618, 64-bit create table t1(c1 int); CREATE TABLE insert into t1 values(1),(2),(3); INSERT 0 3 create table t2(c2 int); CREATE TABLE insert into t2 values(1),(2),(3); INSERT 0 3 -- SESSION A start transaction; START TRANSACTION select pg_backend_pid(); pg_backend_pid ---------------- 803 update t1 set c1 = 11 where c1 = 1; UPDATE 1 -- SESSION B start transaction; START TRANSACTION select pg_backend_pid(); pg_backend_pid ---------------- 843 update t1 set c1 = 22 where c1 = 2; UPDATE 1 -- SESSION C select pg_backend_pid(); pg_backend_pid ---------------- 880 start transaction; START TRANSACTION update t1 set c1 = 33 where c1 = 3; UPDATE 1 delete from t1; -- EN ATTENTE -- SESSION D select pg_backend_pid(); pg_backend_pid ---------------- 914 truncate table t1; -- EN ATTENTE -- SESSION E select pg_backend_pid(); pg_backend_pid ---------------- 944 select * from t1; -- EN ATTENTE -- SESSION F select pg_backend_pid(); pg_backend_pid ---------------- 973 start transaction; START TRANSACTION update t2 set c2 = 11 where c2 = 1; UPDATE 1 -- SESSION F select pg_backend_pid(); pg_backend_pid ---------------- 1007 update t2 set c2 = 111 where c2 = 1; -- EN ATTENTE -- SESSION G select pg_backend_pid(); pg_backend_pid ---------------- 1038 update t2 set c2 = 22 where c2 = 2; UPDATE 1 select pg_sleep(30000); -- EN ATTENTE -- SESSION H select pg_backend_pid(); pg_backend_pid ---------------- 1241 update t1 set c1 = 333 where c1 = 3; -- EN ATTENTE

Le décor est planté, beaucoup d’utilisateurs se plaignent. Première analyse avec une version ancienne du traqueur :

Ouille ?!? Le vieux traqueur a du mal. Les résultats sont faussés car un même process peut apparaître plusieurs fois à 100% d’activité, bloqué par des process différents qui sont eux-mêmes parfois bloqués. Qui sont les assassins, les "final blockers", et qui sont les victimes ?
Avant d’interroger directement les tables du catalogue, tentons d’utiliser le traqueur dans une version plus récente :

./traqueur.sh traqueur 0.08.00beta - outil de diagnostic performance pour PostgreSQL 9.6, 10 INFORMATION, pas d'options de connexions indiquees, utilisation de la base traqueur detectee ... INFORMATION, preparation de la collecte ... INFORMATION, execution de la collecte et presentation des resultats ... busy_pc | distinct_exe | db | pid | pg_user | client_ip | application | query | wait_event_type | blockers ---------+--------------+----------+------+----------+-----------+-------------+--------------------------------------+-----------------+----------- 100 | 1 / 50 | postgres | 880 | postgres | | psql | delete from t1; | Lock | {803} 100 | 1 / 50 | postgres | 914 | postgres | | psql | truncate table t1; | Lock | {803,843} 100 | 1 / 50 | postgres | 944 | postgres | | psql | select * from t1; | Lock | {803,843} 100 | 1 / 50 | postgres | 1007 | postgres | | psql | update t2 set c2 = 111 where c2 = 1; | Lock | {973} 100 | 1 / 50 | postgres | 1038 | postgres | | psql | select pg_sleep(30000); | Timeout | 100 | 1 / 50 | postgres | 1241 | postgres | | psql | update t1 set c1 = 333 where c1 = 3; | Lock | {803,843} (6 lignes)

      La situation est plus claire. Ici, par exemple, le "select * from t1" du process 944 peut être directement bloqué par le process 914 effectuant un "truncate table t1". Mais le process 914 étant lui-même au final bloqué par les process 803 et 843, c’est cette liste {803,843} qui est donnée pour 944. Idem pour 880 et 1241 : ce sont toujours 803 et/ou 843 qui sont coupables sans être victimes.
      Cette version du traqueur donne en effet pour chaque process bloqué par un verrou une liste de ses bloqueurs finaux, c’est à dire une liste de process le bloquant directement ou indirectement et n’attendant pas d’obtenir des verrous. Il ne faut pas directement en conclure qu’ils doivent être tués. Ces bloqueurs vont peut-être finir par libérer les verrous et sont peut-être en train de travailler, même s’ils n’apparaissent pas dans la liste des résultats du traqueur qui n’effectue qu’un sondage.
      Nous allons donc examiner plus attentivement la situation des process 803 et 843 avant de décider de leur sort. Ils ne semblent pas actifs et le traqueur ne va donc pas ici nous aider. Il faut directement interroger pg_stat_activity :

Bon, cela fait 25 minutes que 803 et 843 n’ont rien fait et personne ne peut reprendre la main sur ces sessions. Il va falloir agir. La décision est prise de les tuer. Attention, le travail de leurs transactions en cours sera annulé comme s’ils avaient lancé un ROLLBACK :

select pg_terminate_backend(803); pg_terminate_backend ---------------------- t ./traqueur.sh -d 1 traqueur 0.08.00beta - outil de diagnostic performance pour PostgreSQL 9.6, 10 INFORMATION, pas d'options de connexions indiquees, utilisation de la base traqueur detectee ... INFORMATION, preparation de la collecte ... INFORMATION, execution de la collecte et presentation des resultats ... busy_pc | distinct_exe | db | pid | pg_user | client_ip | application | query | wait_event_type | blockers ---------+--------------+----------+------+----------+-----------+-------------+--------------------------------------+-----------------+---------- 100 | 1 / 10 | postgres | 880 | postgres | | psql | delete from t1; | Lock | {843} 100 | 1 / 10 | postgres | 914 | postgres | | psql | truncate table t1; | Lock | {843} 100 | 1 / 10 | postgres | 944 | postgres | | psql | select * from t1; | Lock | {843} 100 | 1 / 10 | postgres | 1007 | postgres | | psql | update t2 set c2 = 111 where c2 = 1; | Lock | {973} 100 | 1 / 10 | postgres | 1038 | postgres | | psql | select pg_sleep(30000); | Timeout | 100 | 1 / 10 | postgres | 1241 | postgres | | psql | update t1 set c1 = 333 where c1 = 3; | Lock | {843} select pg_terminate_backend(843); pg_terminate_backend ---------------------- t ./traqueur.sh -d 1 traqueur 0.08.00beta - outil de diagnostic performance pour PostgreSQL 9.6, 10 INFORMATION, pas d'options de connexions indiquees, utilisation de la base traqueur detectee ... INFORMATION, preparation de la collecte ... INFORMATION, execution de la collecte et presentation des resultats ... busy_pc | distinct_exe | db | pid | pg_user | client_ip | application | query | wait_event_type | blockers ---------+--------------+----------+------+----------+-----------+-------------+--------------------------------------+-----------------+---------- 100 | 1 / 10 | postgres | 914 | postgres | | psql | truncate table t1; | Lock | {880} 100 | 1 / 10 | postgres | 944 | postgres | | psql | select * from t1; | Lock | {880} 100 | 1 / 10 | postgres | 1007 | postgres | | psql | update t2 set c2 = 111 where c2 = 1; | Lock | {973} 100 | 1 / 10 | postgres | 1038 | postgres | | psql | select pg_sleep(30000); | Timeout | 100 | 1 / 10 | postgres | 1241 | postgres | | psql | update t1 set c1 = 333 where c1 = 3; | Lock | {880} select * from pg_stat_activity where pid = 880; -[ RECORD 1 ]----+------------------------------ datid | 12872 datname | postgres pid | 880 usesysid | 10 usename | postgres application_name | psql client_addr | client_hostname | client_port | -1 backend_start | 2017-07-09 13:16:21.913152+02 xact_start | 2017-07-09 13:31:18.617386+02 query_start | 2017-07-09 13:32:21.314876+02 state_change | 2017-07-09 14:01:31.094092+02 wait_event_type | Client wait_event | ClientRead state | idle in transaction backend_xid | 24840 backend_xmin | query | delete from t1; backend_type | client backend -- SESSION C delete from t1; DELETE 3 rollback; ROLLBACK ./traqueur.sh -d 1 traqueur 0.08.00beta - outil de diagnostic performance pour PostgreSQL 9.6, 10 INFORMATION, pas d'options de connexions indiquees, utilisation de la base traqueur detectee ... INFORMATION, preparation de la collecte ... INFORMATION, execution de la collecte et presentation des resultats ... busy_pc | distinct_exe | db | pid | pg_user | client_ip | application | query | wait_event_type | blockers ---------+--------------+----------+------+----------+-----------+-------------+--------------------------------------+-----------------+---------- 100 | 1 / 10 | postgres | 1007 | postgres | | psql | update t2 set c2 = 111 where c2 = 1; | Lock | {973} 100 | 1 / 10 | postgres | 1038 | postgres | | psql | select pg_sleep(30000); | Timeout |

Après la mort de 803 et 843, c’est le delete lancé par 880 qui a causé un nouveau blocage. Cependant la session "C" du process 880 n’était pas orpheline, un ROLLBACK volontaire y a été effectué et a terminé de libérer les requêtes agissant sur t1. Reste à présent à s’occuper de 973 qui bloque 1007 mais c’est la même logique. 1038 semble bloqué mais il est en fait en train de dormir et ne bloque (pour l’instant) personne.

Conclusion

Le traqueur evolue régulièrement et dispose depuis la 0.08.00 de capacités pour mieux analyser les problèmes de verrouillage. N’hésitez-pas à me poser tout question ou me signaler tout bug que vous pourriez rencontrer dans son utilisation.

Traqueur, problème de verrouillage

Un problème applicatif

Mise à jour : 09/07/2017