Traqueur, problème massif de verrouillage

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

      Dans cet article, nous allons simuler un problème massif de verrouillage. Une session va bloquer une autre session qui va bloquer 500 sessions.
      Démonstration avec PostgreSQL 10 :

pg_lsclusters Ver Cluster Port Status Owner Data directory Log file 9.2 main 5431 online postgres /var/lib/postgresql/9.2/main /var/log/postgresql/postgresql-9.2-main.log 9.3 main 5432 online postgres /var/lib/postgresql/9.3/main /var/log/postgresql/postgresql-9.3-main.log 9.4 main 5433 online postgres /var/lib/postgresql/9.4/main /var/log/postgresql/postgresql-9.4-main.log 9.5 main 5434 online postgres /var/lib/postgresql/9.5/main /var/log/postgresql/postgresql-9.5-main.log 9.6 main 5435 online postgres /var/lib/postgresql/9.6/main /var/log/postgresql/postgresql-9.6-main.log 10 main 5436 online postgres /var/lib/postgresql/10/main /var/log/postgresql/postgresql-10-main.log -- choix de travailler avec la version 10, port 5436 select version(); version ----------------------------------------------------------------------------------------------------------------- PostgreSQL 10rc1 on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 5.4.0-6ubuntu1~16.04.4) 5.4.0 20160609, 64-bit show max_connections; max_connections ----------------- 2000 (1 ligne) -- preparation environnement create table t1(c1 int); CREATE TABLE insert into t1 values(1),(2),(3); INSERT 0 3 -- session A select pg_backend_pid(); pg_backend_pid ---------------- 6584 (1 ligne) start transaction; START TRANSACTION update t1 set c1 = 11 where c1 = 1; UPDATE 1 update t1 set c1 = 22 where c1 = 2; UPDATE 1 -- session B select pg_backend_pid(); pg_backend_pid ---------------- 6598 (1 ligne) start transaction; START TRANSACTION update t1 set c1 = 33 where c1 = 3; UPDATE 1 update t1 set c1 = 222 where c1 = 2; -- EN ATTENTE !!!! -- 500 * session C -- 10 appels à une ligne en bash effectuant 50 connexions for i in {1..50}; do psql -p 5436 -c "update t1 set c1 = 333 where c1 = 3" & done ... for i in {1..50}; do psql -p 5436 -c "update t1 set c1 = 333 where c1 = 3" & done -- EN ATTENTE !!!

      Le décor est planté. La situation qui est décrite par les utilisateurs est une situation de blocage complet, pas un simple ralentissement.
      Plutôt que de lancer le traqueur par défaut, nous allons donc utiliser une fonctionnalité introduite en 0.12.00 consistant à faire un unique cliché avec -d 0. Le chronométrage de psql est par ailleurs activé afin de connaître la durée de la requête principale :

time ./traqueur.sh -c "-p 5436 -d traqueur" -t -d 0 traqueur 0.12.00beta - outil de diagnostic performance pour PostgreSQL 9.3 => 10 INFORMATION, version de PostgreSQL detectee : 100000 INFORMATION, preparation de la collecte ... INFORMATION, execution de la collecte et presentation des resultats ... Temps : 0,111 ms Temps : 0,579 ms Temps : 9,234 ms Temps : 2,483 ms Temps : 1,283 ms Temps : 38,924 ms Temps : 5,360 ms Temps : 0,637 ms Temps : 0,360 ms Temps : 2,048 ms Temps : 0,228 ms Durée : 16097,236 ms (00:16,097) Temps : 0,902 ms Temps : 0,666 ms busy_pc | distinct_exe | db | pid | pg_user | client_ip | application | query | wait_event_type | blockers ---------+--------------+----------+-------+----------+-----------+-------------+--------------------------------------+-----------------+---------- 100 | 1 / 1 | postgres | 6598 | postgres | | psql | update t1 set c1 = 222 where c1 = 2; | Lock | {6584} 100 | 1 / 1 | postgres | 6840 | postgres | | psql | update t1 set c1 = 333 where c1 = 3 | Lock | {6584} 100 | 1 / 1 | postgres | 6847 | postgres | | psql | update t1 set c1 = 333 where c1 = 3 | Lock | {6584} ... 100 | 1 / 1 | postgres | 11138 | postgres | | psql | update t1 set c1 = 333 where c1 = 3 | Lock | {6584} 100 | 1 / 1 | postgres | 11139 | postgres | | psql | update t1 set c1 = 333 where c1 = 3 | Lock | {6584} 100 | 1 / 1 | postgres | 11140 | postgres | | psql | update t1 set c1 = 333 where c1 = 3 | Lock | {6584} (501 lignes) real 0m17.835s user 0m0.220s sys 0m0.148s time ./traqueur.sh -c "-p 5436 -d traqueur" -d 0 -t -o "itquery, tquery, blockers" -n traqueur 0.12.00beta - outil de diagnostic performance pour PostgreSQL 9.3 => 10 INFORMATION, version de PostgreSQL detectee : 100000 INFORMATION, preparation de la collecte ... INFORMATION, execution de la collecte et presentation des resultats ... Temps : 0,109 ms Temps : 0,582 ms Temps : 8,441 ms Temps : 2,338 ms Temps : 1,249 ms Temps : 40,898 ms Temps : 93,258 ms Temps : 5,445 ms Temps : 0,630 ms Temps : 0,343 ms Temps : 1,388 ms Temps : 0,176 ms Durée : 16164,671 ms (00:16,165) Temps : 0,927 ms Temps : 0,692 ms busy_pc | distinct_exe | itquery | tquery | blockers ---------+--------------+------------+------------------------------------+---------- 50000 | 499 / 500 | 2068084115 | update t1 set c1 = 0 where c1 = 0 | {6584} 100 | 1 / 1 | 1693947591 | update t1 set c1 = 0 where c1 = 0; | {6584} (2 lignes) Temps : 5,280 ms real 0m16.753s user 0m0.220s sys 0m0.132s

      L’analyse a mis entre 16 et 18 secondes et donne bien l’unique coupable quel que soit l’angle utilisé pour afficher les résultats, le process 6584. Une exécution du traqueur par défaut aurait pris 15min et aurait donné les mêmes résultats, n’hésitez pas à interromptre le traqueur avec CTRL+C si la durée d’analyse est anormale. Relancez-la ensuite avec -d 0.
      Le niveau de récursivité utilisé par défaut pour déterminer les bloqueurs finaux est 2. La requête hiérarchique utilisée par le traqueur part des bloqueurs finaux. Il est donc possible de baisser le niveau de récursivité afin d’obtenir plus rapidement le ou les coupables. Démonstration avec un niveau de 1 (-i 1) :

time ./traqueur.sh -c "-p 5436 -d traqueur" -d 0 -t -o "itquery, tquery, blockers" -n -i 1 traqueur 0.12.00beta - outil de diagnostic performance pour PostgreSQL 9.3 => 10 INFORMATION, version de PostgreSQL detectee : 100000 INFORMATION, preparation de la collecte ... INFORMATION, execution de la collecte et presentation des resultats ... Temps : 0,108 ms Temps : 0,571 ms Temps : 8,604 ms Temps : 2,330 ms Temps : 1,245 ms Temps : 55,130 ms Temps : 1,242 ms Temps : 5,453 ms Temps : 0,620 ms Temps : 0,315 ms Temps : 1,257 ms Temps : 0,163 ms Temps : 973,882 ms Temps : 0,872 ms Temps : 0,924 ms busy_pc | distinct_exe | itquery | tquery | blockers ---------+--------------+------------+------------------------------------+---------- 49900 | 498 / 499 | 2068084115 | update t1 set c1 = 0 where c1 = 0 | 100 | 1 / 1 | 1693947591 | update t1 set c1 = 0 where c1 = 0; | {6584} 100 | 1 / 1 | 2068084115 | update t1 set c1 = 0 where c1 = 0 | {6584} (3 lignes) Temps : 5,160 ms real 0m1.483s user 0m0.260s sys 0m0.092s

      L’analyse a pris 1s5 (moins de 1 seconde pour la requête principale) au lieu de 18s. Différence : les résultats sont moins précis puisque tous les bloqués ne sont plus associés à leur bloqueur final au niveau des résultats.
      PostgreSQL 9.6 apporte une fonction pg_blockings_pid(pid) qui peut également être utilisée. La traque des bloqueurs finaux est essentielle donc la méthode actuelle sera conservée au moins jusque la fin de vie de la 9.5.
      Il faut également noter que pg_blockings_pids ne donne de toute façon pas directement les bloqueurs finaux. Démonstration en filtrant sur un seul process via l’option -w et en ajoutant pg_blockings_pid(pid) au niveau de la liste des colonnes via l’option -o :

time ./traqueur.sh -c "-p 5436 -d traqueur" -d 0 -o "pid, itquery, tquery, blockers, pg_blocking_pids(pid) as direct_blockers" -n -w "11138" -x traqueur 0.12.00beta - outil de diagnostic performance pour PostgreSQL 9.3 => 10 INFORMATION, version de PostgreSQL detectee : 100000 INFORMATION, preparation de la collecte ... INFORMATION, execution de la collecte et presentation des resultats ... -[ RECORD 1 ] busy_pc | 100 distinct_exe | 1 / 1 pid | 11138 itquery | 2068084115 tquery | update t1 set c1 = 0 where c1 = 0 blockers | {6584} direct_blockers | {6847,6840,6869,6882,6896,6888,6900,6903,6911,6919,6930,6933,6925,6936,6902,6940,6945,6943,6946,6948,6963,6976,6986,6994,6989,6993,7006,7004,6998,7010,7022,7025,7028,7053,7054,7056, 7059,7061,7063,7064,7065,7066,7067,7069,7068,7071,7070,7072,7073,7074,7311,7359,7362,7366,7357,7348,7369,7371,7355,7394,7397,7391,7393,7420,7424,7419,7430,7436,7414,7437,7450,7441,7448,7459,7461,7465, 7464,7463,7466,7481,7479,7492,7494,7489,7500,7506,7510,7511,7512,7517,7514,7516,7519,7518,7520,7524,7522,7523,7521,7525,7801,7792,7824,7831,7834,7822,7821,7839,7836,7854,7853,7857,7862,7861,7863, 7864,7873,7880,7885,7868,7891,7898,7892,7893,7904,7905,7910,7916,7914,7923,7922,7943,7950,7952,7953,7951,7959,7957,7958,7963,7960,7965,7970,7968,7972,7974,7973,7975,7976,7977,8207,8218,8205,8210,8215, 8222,8235,8269,8274,8271,8279,8265,8292,8293,8281,8303,8308,8310,8315,8327,8329,8321,8319,8335,8333,8349,8350,8361,8364,8368,8375,8378,8355,8401,8410,8409,8406,8414,8417,8418,8419,8420,8422,8421, 8424,8423,8425,8426,8427,8428,8647,8703,8701,8709,8717,8735,8736,8738,8745,8744,8757,8754,8746,8756,8764,8777,8771,8772,8763,8769,8778,8790,8800,8802,8807,8816,8811,8817,8834,8846,8847,8850,8857,8863, 8866,8864,8869,8871,8872,8874,8873,8875,8877,8879,8880,8876,8878,8881,8882,8883,9135,9152,9155,9162,9148,9166,9181,9165,9171,9194,9189,9197,9185,9203,9211,9204,9212,9218,9228,9232,9229,9242,9262, 9274,9277,9282,9284,9294,9299,9291,9304,9301,9305,9314,9316,9317,9318,9319,9322,9321,9323,9324,9326,9327,9328,9330,9332,9333,9331,9334,9593,9604,9622,9625,9607,9620,9631,9637,9628,9627,9618,9644,9654, 9638,9655,9657,9653,9674,9671,9680,9692,9646,9700,9702,9694,9703,9720,9722,9725,9724,9732,9740,9741,9742,9746,9753,9754,9767,9770,9769,9772,9776,9778,9779,9781,9780,9783,9782,9784,9785,10035,10045, 10046,10055,10067,10069,10071,10062,10079,10059,10090,10100,10094,10106,10107,10108,10129,10134,10139,10158,10151,10140,10149,10165,10171,10181,10184,10183,10182,10190,10202,10204,10212,10211,10205, 10217,10220,10221,10225,10223,10224,10226,10228,10231,10233,10232,10234,10235,10236,10237,10491,10492,10493,10500,10513,10524,10532,10527,10545,10543,10530,10551,10544,10548,10555,10556,10564,10567 ,10573,10575,10588,10578,10589,10596,10594,10606,10633,10626,10648,10647,10649,10650,10655,10652,10664,10656,10671,10666,10667,10675,10677,10681,10682,10683,10686,10685,10687,10684,10688,10689,10921, 10959,10958,10957,10960,10990,10987,10993,11002,11003,11000,11009,11010,10982,10998,11021,11014,11031,11038,11046,11050,11052,11059,11065,11071,11067,11054,11095,11098,11081,11106,11107,11108,11112 ,11117,11115,11122,11118,11128,11129,11132,11134,11131,11133,11135,11137,11136} real 0m16.616s user 0m0.252s sys 0m0.112s

      pg_blockings_pids donne une longue liste de process constituant les bloqueurs directs du processs 11138. Tous ces process ne sont cependant pas coupables car ils sont eux-mêmes bloqués par le process 6584 et pg_blocking_pids ne vous donnera pas cette information. Le traqueur conserve donc toute son utilité dans la traque des bloqueurs finaux même en 9.6 et versions supérieures de PostgreSQL.

Mise à jour : 01/10/2017