Traqueur, activité négligeable

La menace fantôme

Téléchargement du traqueur pour PostgreSQL 11, 12, 13, 14 et 15
Téléchargement du traqueur pour PostgreSQL 10
Téléchargement du traqueur pour PostgreSQL 9.6
Téléchargement du traqueur pour PostgreSQL 9.5
Téléchargement du traqueur pour PostgreSQL 9.4
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 permet de cerner la cause des ralentissements des traitements lorsque l’activité a lieu en base. Il permet donc de ne pas passer inutilement du temps et de l’argent à tuner la base de données, à ajouter de la puissance CPU, à poser des index etc. si les causes de ralentissement sont extérieures.
      Il est cependant parfois assez difficile de convaincre les autres acteurs que vous ne pouvez rien faire pour eux. Dans cet article, je vais utiliser un test case mais il simule parfaitement un cas réel que j’ai rencontré plusieurs fois en production. Nous sommes en plein milieu du traitement lent qui boucle, démonstration :

select version(); version ---------------------------------------------------------------------------------------------------------------- PostgreSQL 10.0 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) create table t1(c1 int); CREATE TABLE Temps : 3,093 ms with recursive serie(i) as (values(1) UNION ALL select i + 1 from serie where i < 10000) postgres-# insert into t1 select i from serie; INSERT 0 10000 \dt+ t1 Liste des relations Schéma | Nom | Type | Propriétaire | Taille | Description --------+-----+-------+--------------+--------+------------- public | t1 | table | postgres | 384 kB | (1 ligne) -- session "boucle" select pg_backend_pid(); pg_backend_pid ---------------- 3956 (1 ligne) select count(1) from t1 ; count ------- 10000 (1 ligne) \watch 1 jeu. 02 nov. 2017 16:35:38 CET (chaque 1s) count ------- 10000 (1 ligne) Temps : 1,981 ms ... Temps : 1,959 ms ... Temps : 1,965 ms -- autre session qui dort postgres=# select pg_backend_pid(); pg_backend_pid ---------------- 4321 (1 ligne) postgres=# select pg_sleep(1000000); ...

      Le décor est planté. Une requête très rapide est régulièrement lancée par le process 3956 qui doit l’exécuter des dizaines de milliers de fois pour achever le traitement. Le process ne fait pas RIEN en base mais le temps d’activité sur PostgreSQL est négligeable par rapport au temps horloge écoulé.
      Le traqueur va immédiatement découvrir le pot aux roses :

time ./t -c "-p 5436 -d traqueur" traqueur 1.01.00 - outil de diagnostic performance pour PostgreSQL 9.3 => 10 INFORMATION, connecte a la base traqueur INFORMATION, version de PostgreSQL detectee : 100000 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 | 4321 | postgres | | psql | select pg_sleep(1000000); | Timeout | (1 ligne) real 0m5.545s user 0m0.248s sys 0m0.116s time ./t -c "-p 5436 -d traqueur" -s 1 traqueur 1.01.00 - outil de diagnostic performance pour PostgreSQL 9.3 => 10 INFORMATION, connecte a la base traqueur INFORMATION, version de PostgreSQL detectee : 100000 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 / 500 | postgres | 4321 | postgres | | psql | select pg_sleep(1000000); | Timeout | (1 ligne) real 0m6.006s user 0m0.384s sys 0m0.188s

      Pas de process 3956 alors que nous sommes censés être en plein coeur du travail sur la base. Dans la réalité, nous effectuerions plusieurs sessions de traque et/ou une session de traque plus longue afin d’infirmer ou confirmer ce résultat. Le plus simple serait d’ailleurs d’ailleurs d’exécuter le traqueur en mode batch (option -b) puis de consulter un rapport sur une période significative (option -r). Mais la conclusion serait invariablement la suivante : le process 3956 ne travaille pas ou travaille peu sur la base.
      Nous aurions bien sûr fini par tomber sur le process mais, ici, nous ne l’avons pas détecté une fois même en collectant l’activité tous les centièmes de secondes (-s 1). Il faut chercher ailleurs qu’au niveau base les causes de lenteur du traitement exécuté par le process 3956.
      En effet, ce process ne fait certes pas RIEN en base puisque nous savons que de nombreuses requêtes sont exécutées. Mais cela n’a pas d’importance pour optimiser la performance du traitement.
      Le traqueur passe essentiellement son temps à dormir. Il n’est pas un outil d’audit ou de trace et ne cherche pas à faire la différence entre rien et quasi rien. Cela permet de limiter drastiquement sa consommation de ressources, la paresse a parfois du bon.
      Il ne faut cependant pas négliger l’aspect psychologique. Comme le process 3956 n’apparaît pas, un interlocuteur pourrait douter de la pertinence de l’analyse par le traqueur. Vous pourriez vous même avoir des doutes sur le fait que vous êtes en train d’analyser le bon cluster. J’ai donc été amené à ajouter la possibilité d’éliminer les temps de sommeil, démonstration :

time ./t -c "-p 5436 -d traqueur" -s 0 traqueur 1.01.00 - outil de diagnostic performance pour PostgreSQL 9.3 => 10 INFORMATION, connecte a la base traqueur INFORMATION, version de PostgreSQL detectee : 100000 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 / 5000 | postgres | 4321 | postgres | | psql | select pg_sleep(1000000); | Timeout | 0 | 3 / 3 | postgres | 3956 | postgres | | psql | select count(1) from t1 ; | | (2 lignes) real 0m13.614s user 0m1.068s sys 0m0.876s

      Le process 3956 et la petite requête apparaissent finalement. Cependant, la colonne busy_pc donnant le pourcentage d’activité lié au process 3956 affiche 0 en raison de l’arrondi. Nous n’avons donc rien appris de plus mais nous avons VU le process et la requête, ce qui peut rassurer sur la pertinence de la session de traque.
      Je déconseille fortement l’utilisation de -s 0 dans l’immense majorité des cas car le traqueur consomme alors BEAUCOUP de ressources. C’est bien sûr particulièrement ennuyeux pour un outil de troubleshooting et de suivi des performances qui sera souvent utilisé alors que la situation est déjà tendue.

Mise à jour : 04/11/2017