Traqueur, le chargement interminable

Transactions inutiles

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

Le serveur ne fait pourtant rien ?!?

      Dans une entreprise lointaine, vous êtes sollicité car un chargement en base PostgreSQL est "lent". La 1ère partie constituant une table de travail prend déjà plus de 10 heures. Un environnement de test existe, il est à l’image de la production mais traite 5% de la volumétrie habituellement chargée. Plusieurs intervenants ont déjà des avis "Il faudrait une baie full flash" "Le chargement ne parvient pas à charger la machine donc parallélisons-le" etc.
      Vous n’avez pas d’avis. Vous avez le traqueur que vous décidez de faire tourner pendant cette 1ère partie :

./traqueur96.sh -w "select pid from pg_stat_activity where application_name = 'BATCH3'" traqueur 0.05.06.96beta - outil de diagnostic performance pour PostgreSQL 9.6 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 | blocker ---------+--------------+----------+-------+----------+-----------+-------------+------------------------------------------------------------------+--------- 92 | 45 / 46 | postgres | 20786 | postgres | | BATCH3 | insert into xxxxxx_xxx values(xxxxxxx_xxxxxxxxx , trunc(xxx + 1) | (1 ligne) ./traqueur96.sh -w "select pid from pg_stat_activity where application_name = 'BATCH3'" -s 1 traqueur 0.05.06.96beta - outil de diagnostic performance pour PostgreSQL 9.6 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 | blocker ---------+--------------+----------+-------+----------+-----------+-------------+------------------------------------------------------------------+--------- 94 | 445 / 469 | postgres | 20786 | postgres | | BATCH3 | insert into xxxxxx_xxx values(xxxxxxx_xxxxxxxxx , trunc(xxx + 1) | (1 ligne) ./traqueur96.sh -w "select pid from pg_stat_activity where application_name = 'BATCH3'" -p traqueur 0.05.06.96beta - outil de diagnostic performance pour PostgreSQL 9.6 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 | blocker | non_cpu_pc | mem_en_mo | swapped_en_mo ---------+--------------+----------+--------+----------+-----------+-------------+------------------------------------------------------------------+---------+------------+-----------+--------------- 100 | 50 / 50 | postgres | 20786 | postgres | | BATCH3 | insert into xxxxxx_xxx values(xxxxxxx_xxxxxxxxx , trunc(xxx + 1) | | 85 | 4 | 0 (1 ligne) Charge CPU moyennne globale ----------------------------- 5 (1 ligne) temps_cpu_user_en_s | temps_cpu_systeme_en_s | temps_cpu_idle_en_s | temps_io_en_s ---------------------+------------------------+---------------------+--------------- 0 | 0 | 19 | 0 (1 ligne) ./traqueur96.sh -w "select pid from pg_stat_activity where application_name = 'BATCH3'" -s 1 -o "xact_start" traqueur 0.05.06.96beta - outil de diagnostic performance pour PostgreSQL 9.6 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 | xact_start ---------+--------------+------------------------------- ... 0 | 1 / 1 | 2016-12-19 01:28:16.106782+01 0 | 1 / 1 | 2016-12-19 01:28:16.117967+01 0 | 1 / 1 | 2016-12-19 01:28:16.133089+01 0 | 1 / 1 | 2016-12-19 01:28:16.14417+01 0 | 1 / 2 | 2016-12-19 01:28:16.159626+01 (422 lignes) real 37m35,829s user 0m25,304s sys 0m14,568s
Commit, commit, commit...stop !

      Le chargement a duré 37min36. Pendant ce temps, vous avez fait tourner 4 fois le traqueur avec différentes options et vous avez recueilli beaucoup d’informations.

      On vous demande vos conclusions et ce qu’il faut faire. Les données de la table de travail ne sont pas précieuses, elles peuvent être rechargées et ne sont utilisées que pour la suite du traitement. Cela vous donne une première idée qui a l’avantage de ne pas devoir toucher au code du chargement :

select version(); version --------------------------------------------------------------------------------------------------- PostgreSQL 9.6.1 on x86_64-pc-linux-gnu, compiled by gcc (Debian 6.2.0-10) 6.2.0 20161027, 64-bit (1 ligne) select * from pg_class where relname = 'xxxxxx_xxx'; -[ RECORD 1 ]-------+----------- relname | xxxxxx_xxx ... relhasindex | f relisshared | f relpersistence | p ... ALTER TABLE xxxxxx_xxx SET UNLOGGED; ALTER TABLE select * from pg_class where relname = 'xxxxxx_xxx'; -[ RECORD 1 ]-------+----------- relname | xxxxxx_xxx ... relhasindex | f relisshared | f relpersistence | u ...
UNLOGGED

      Vous avez modifié la persistence des données de la table de travail. Impossible de passer cette table en table temporaire puisque ses données sont interrogées par d’autres sessions dans la suite du traitement. Mais il ne sert rien de les protéger en cas de crash du serveur ou autre puisqu’elles sont inutiles une fois le traitement terminé.
      Le chargement est relancé après cette modification et vous le suivez encore une fois avec le traqueur :

./traqueur96.sh -w "select pid from pg_stat_activity where application_name = 'BATCH3'" -p traqueur 0.05.06.96beta - outil de diagnostic performance pour PostgreSQL 9.6 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 | blocker | non_cpu_pc | mem_en_mo | swapped_en_mo ---------+--------------+----------+------+----------+-----------+-------------+------------------------------------------------------------------+---------+------------+-----------+--------------- 54 | 27 / 27 | postgres | 1374 | postgres | | BATCH3 | insert into xxxxxx_xxx values(xxxxxxx_xxxxxxxxx , trunc(xxx + 1) | | 32 | 0 | 0 (1 ligne) Charge CPU moyennne globale ----------------------------- 21 (1 ligne) temps_cpu_user_en_s | temps_cpu_systeme_en_s | temps_cpu_idle_en_s | temps_io_en_s ---------------------+------------------------+---------------------+--------------- 2 | 2 | 14 | 0 (1 ligne) real 3m25,094s user 0m11,508s sys 0m21,148s
Une grande transaction

      Le chargement n’est plus actif qu’à 54% au niveau PostgreSQL mais la part non CPU est tombée à 32%. Au niveau global le système est à présent chargé à 21%. Autrement dit le travail est plus intense. La durée du chargement est passée à 3min25s. Cependant passer une table en UNLOGGED n’est pas applicable dans la majeure partie des cas et vous conseillez de modifier le programme. COPY ne peut pas être utilisé car il ne s’agit pas d’un simple chargement de données brutes, des fonctions PostgreSQL sont appelées à l’insertion. Mais les transactions inutiles doivent être éliminées !
      Une modification est effectuée pour ouvrir une transaction (START TRANSACTION) et valider en fin de chargement (COMMIT) au lieu de valider après chaque INSERT. Le chargement est relancé après cette modification et vous le suivez encore une fois avec le traqueur :

./traqueur96.sh -w "select pid from pg_stat_activity where application_name = 'BATCH3'" -s 1 -o "xact_start" traqueur 0.05.06.96beta - outil de diagnostic performance pour PostgreSQL 9.6 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 | xact_start ---------+--------------+------------------------------- 71 | 354 / 354 | 2016-12-19 18:04:38.292912+01 (1 ligne) ./traqueur96.sh -w "select pid from pg_stat_activity where application_name = 'BATCH3'" -p traqueur 0.05.06.96beta - outil de diagnostic performance pour PostgreSQL 9.6 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 | blocker | non_cpu_pc | mem_en_mo | swapped_en_mo ---------+--------------+----------+------+----------+-----------+-------------+------------------------------------------------------------------+---------+------------+-----------+--------------- 80 | 40 / 40 | postgres | 1616 | postgres | | BATCH3 | insert into xxxxxx_xxx values(xxxxxxx_xxxxxxxxx , trunc(xxx + 1) | | 21 | 0 | 0 (1 ligne) Charge CPU moyennne globale ----------------------------- 28 (1 ligne) temps_cpu_user_en_s | temps_cpu_systeme_en_s | temps_cpu_idle_en_s | temps_io_en_s ---------------------+------------------------+---------------------+--------------- 3 | 0 | 14 | 0 (1 ligne) real 2m14,678s user 0m9,100s sys 0m5,744s
La grenouille qui voulait se faire aussi grosse que le boeuf

      La 1ère session du traqueur montre que le travail de modification a bien été effectué. Vous relevez une seule transaction pour 354 exécutions distinctes.
      La 2ème session montre que le taux d’activité au niveau PostgreSQL a augmenté à 80% et on vous dit que la durée du chargement est tombée à 2min15.
      Ces multiples transactions étaient coûteuses mais pourquoi ne pas réduire aussi le nombre d’exécutions ? Il est possible d’insérer de multiple lignes avec un seul INSERT et une seule clause VALUES avec PostgreSQL (voir cet article). Le programme est modifié en ce sens et vous relancez le traqueur :

./traqueur96.sh -w "select pid from pg_stat_activity where application_name = 'BATCH3'" -p traqueur 0.05.06.96beta - outil de diagnostic performance pour PostgreSQL 9.6 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 | blocker | non_cpu_pc | mem_en_mo | swapped_en_mo ---------+--------------+----------+------+----------+-----------+-------------+------------------------------------+---------+------------+-----------+--------------- 100 | 1 / 50 | postgres | 1707 | postgres | | BATCH3 | insert into xxxxxx_xxx values +| | 77 | 7668 | 444 | | | | | | | (xxxxxxx_xxxxxxxxx , trunc(xxx + 1 | | | | (1 ligne) Charge CPU moyennne globale ----------------------------- 61 (1 ligne) temps_cpu_user_en_s | temps_cpu_systeme_en_s | temps_cpu_idle_en_s | temps_io_en_s ---------------------+------------------------+---------------------+--------------- 4 | 7 | 24 | 49 (1 ligne) psql: la connexion au serveur a été coupée de façon inattendue Le serveur s’est peut-être arrêté anormalement avant ou durant le traitement de la requête. ...

      BOUM !!!!! Le mieux est l’ennemi du bien. Une seul instruction INSERT ça ne passe pas. Le traqueur montre que le process de chargement consomme toute la RAM du serveur, tout le SWAP et finit par faire crasher PostgreSQL. Le programme est modifié pour que chaque INSERT charge 100 lignes à la fois. Le programme est modifié en ce sens et vous relancez le traqueur :

./traqueur96.sh -w "select pid from pg_stat_activity where application_name = 'BATCH3'" -p traqueur 0.05.06.96beta - outil de diagnostic performance pour PostgreSQL 9.6 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 | blocker | non_cpu_pc | mem_en_mo | swapped_en_mo ---------+--------------+----------+------+----------+-----------+-------------+------------------------------------+---------+------------+-----------+--------------- 92 | 46 / 46 | postgres | 1860 | postgres | | BATCH3 | insert into xxxxxx_xxx values +| | 6 | 17 | 0 | | | | | | | (xxxxxxx_xxxxxxxxx , trunc(xxx + 1 | | | | (1 ligne) Charge CPU moyennne globale ----------------------------- 25 (1 ligne) temps_cpu_user_en_s | temps_cpu_systeme_en_s | temps_cpu_idle_en_s | temps_io_en_s ---------------------+------------------------+---------------------+--------------- 4 | 1 | 15 | 0 (1 ligne) real 0m37,086s user 0m1,856s sys 0m0,216s
60 fois plus rapide !

      Le chargement qui durait 37 minutes au départ s’achève ici en 37s. 37s d’activité intense comme le montre le traqueur (92% et un CPU entièrement sollicité) mais le gain est spectaculaire. En production cette partie du chargement durait plus de 10 heures, elle s’achèvera logiquement en moins de 15 minutes, mission réussie.

Mise à jour : 19/12/2016