Traqueur, problème de verrouillage passé

Enquêter a posteriori

Téléchargement du traqueur pour PostgreSQL 9.4, 9.5, 9.6, 10, 11 et 12
Téléchargement du traqueur pour PostgreSQL 9.3
Journal des changements
Signalement de bugs via le forum
Licence identique à celle de PostgreSQL, open source type BSD
Dossier des versions

      Le traqueur s’intéresse aux sessions actives. Sur un problème de verrouillage, si vous l’utilisez en interactif, il vous donnera les coupables que vous pourrez retrouver manuellement dans pg_stat_activity et pg_prepared_xacts.
      Le cas est un peu plus complexe si le problème n’est plus en cours. Le principe du traqueur est de ne s’intéresser qu’aux sessions actives. Vous retrouverez donc les victimes mais, si les coupables n’ont pas été suffisamment actifs, alors il passeront à travers les mailles du filet.
      Pallier cet inconvénient est l’objet d’une nouvelle option -u introduite par la version 2.03.00 du traqueur qui peut être combinée avec l’option -b (mode batch). Les informations sur les process et transactions préparées bloquant d’autres sessions sont enregistrées à chaque collecte dans deux tables traqueur_bloqueurs_process et traqueur_bloqueurs_transactions.
      Démonstration avec PostgreSQL 9.3 :

select version(); version ------------------------------------------------------------------------------------------------------------------ PostgreSQL 9.3.20 on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 5.4.0-6ubuntu1~16.04.4) 5.4.0 20160609, 64-bit (1 ligne) -- le traqueur tourne en mode batch nohup ./traqueur.sh -b L -u & tail -f nohup.out INFORMATION, pas d'options de connexions indiquees, utilisation de la base traqueur detectee ... INFORMATION, connecte a la base traqueur INFORMATION, version de PostgreSQL detectee : 90320 INFORMATION, preparation de la collecte ... INFORMATION, execution de la collecte ... -- session A set application_name=appA; SET create table t1(c1 int); CREATE TABLE create table t2(c2 int); CREATE TABLE start transaction; START TRANSACTION insert into t1(c1) values(1); INSERT 0 1 -- session B set application_name=appB; SET start transaction; START TRANSACTION insert into t1(c1) values(2); INSERT 0 1 prepare transaction 'patanok'; PREPARE TRANSACTION -- session C set application_name=appC; SET start transaction; START TRANSACTION insert into t2(c2) values(1); INSERT 0 1 -- session D set application_name=appD; SET start transaction; START TRANSACTION insert into t2(c2) values(2); INSERT 0 1 prepare transaction 'nouka'; PREPARE TRANSACTION -- session E set application_name=appE; SET truncate table t1; -- en attente ! -- session F set application_name=appF; SET select * from t1; -- en attente !

      Le décor est planté, le process de la session d’appA et la transaction préparée par appB bloquent la session de l’application appE et indirectement celle de l’application appF. Le process de l’application appC et la transaction préparée par appD possèdent des verrous mais ne bloquent pour l’instant personne.
      Que dit le traqueur en interactif ?

./traqueur.sh traqueur 2.03.00 - outil de diagnostic performance pour PostgreSQL 9.3 => 11 INFORMATION, pas d'options de connexions indiquees, utilisation de la base traqueur detectee ... INFORMATION, connecte a la base traqueur INFORMATION, version de PostgreSQL detectee : 90320 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 | blockers ---------+--------------+----------+-------+----------+-----------+-------------+-------------------------+----------- 100 | 1 / 50 | postgres | 14749 | postgres | | appe | truncate table t1; | {0,14513} 100 | 1 / 50 | postgres | 14810 | postgres | | appf | select * from t1; | {0,14513} 100 | 2 / 50 | traqueur | 14503 | postgres | | traqueur | execute traqueur_sleep; | (3 lignes)

      Nous trouvons ici nos 2 sessions appe et appf bloquées par un process (pid 14513) et une transaction préparée (0). 14513 n’est pas actif donc il n’apparaît pas. Cependant, il est simple si le problème est en cours d’en savoir plus sur lui :

\x Affichage étendu activé. select * from pg_stat_activity where pid = 14513; -[ RECORD 1 ]----+------------------------------ datid | 12068 datname | postgres pid | 14513 usesysid | 10 usename | postgres application_name | appa client_addr | client_hostname | client_port | -1 backend_start | 2017-12-22 11:06:09.969932+01 xact_start | 2017-12-22 11:06:34.93202+01 query_start | 2017-12-22 11:06:42.989482+01 state_change | 2017-12-22 11:06:42.990221+01 waiting | f state | idle in transaction query | insert into t1(c1) values(1);

      Supposons à présent que le problème ne soit PLUS en cours et que l’on vous demande ce qui a bien pu se passer. Le traqueur tournant en mode batch va nous donner la réponse :

psql traqueur set search_path=traqueur; SET \d Liste des relations Schéma | Nom | Type | Propriétaire ----------+---------------------------------+-------+-------------- traqueur | traqueur_bloqueurs_process | table | postgres traqueur | traqueur_bloqueurs_transactions | table | postgres traqueur | traqueur_sessions_actives | table | postgres (3 lignes) select dtcol, pid, application_name, blockers from traqueur_sessions_actives where dtcol between timestamp '2017-12-22 11:20:00' and timestamp '2017-12-22 11:21:00'; dtcol | pid | application_name | blockers -------------------------------+-------+------------------+----------- 2017-12-22 11:20:08.020736+01 | 14749 | appe | {0,14513} 2017-12-22 11:20:08.020736+01 | 14810 | appf | {0,14513} 2017-12-22 11:20:18.032776+01 | 14749 | appe | {0,14513} 2017-12-22 11:20:18.032776+01 | 14810 | appf | {0,14513} 2017-12-22 11:20:28.040841+01 | 14749 | appe | {0,14513} 2017-12-22 11:20:28.040841+01 | 14810 | appf | {0,14513} 2017-12-22 11:20:38.053496+01 | 14749 | appe | {0,14513} 2017-12-22 11:20:38.053496+01 | 14810 | appf | {0,14513} 2017-12-22 11:20:48.066396+01 | 14749 | appe | {0,14513} 2017-12-22 11:20:48.066396+01 | 14810 | appf | {0,14513} 2017-12-22 11:20:58.079023+01 | 14749 | appe | {0,14513} 2017-12-22 11:20:58.079023+01 | 14810 | appf | {0,14513} (12 lignes) select distinct datname, pid, usename, application_name, state, query from traqueur_bloqueurs_process where dtcol between timestamp '2017-12-22 11:20:00' and timestamp '2017-12-22 11:21:00'; datname | pid | usename | application_name | state | query ----------+-------+----------+------------------+---------------------+------------------------------- postgres | 14513 | postgres | appa | idle in transaction | insert into t1(c1) values(1); (1 ligne) select distinct transaction, gid, owner, database from traqueur_bloqueurs_transactions where dtcol between timestamp '2017-12-22 11:20:00' and timestamp '2017-12-22 11:21:00'; transaction | gid | owner | database -------------+---------+----------+---------- 496086 | patanok | postgres | postgres (1 ligne)

Conclusion

      Vous pouvez ainsi obtenir davantage d’informations sur les méchants bloqueurs finaux que les simples numéros de process.

Mise à jour : 22/12/2017