Traqueur, type d’événement d’attente : IO

IO lentes, IO rapides ou pas d’IO du tout ?

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

      La communauté PostgreSQL travaille bien. Certaines avancées ne sont pas aussi spectaculaires que le partitionnement natif mais sont cependant essentielles pour les administrateurs. La version 10 ne déroge pas à la règle en ajoutant de nouvelles informations concernant les événements d’attente à pg_stat_activity.
      Le principe du traqueur consiste justement à réaliser un sondage sur pg_stat_activity. Chaque information ajoutée est donc précieuse.
      Nous trouvons à présent le type d’événement "IO", les entrées/sorties, les lectures/écritures de donnéees mais comment l’interpréter ? 1ère session de traque avec PostgreSQL 10 :

select version(); version ----------------------------------------------------------------------------------------------------- PostgreSQL 10beta1 on x86_64-pc-linux-gnu, compiled by gcc (Debian 6.3.0-16) 6.3.0 20170425, 64-bit create table geants( idu uuid, dtn date, genre char(1), taille smallint, masse smallint, actif boolean, devise varchar(128), pw smallint, heureux boolean, couleur varchar(8), veteran boolean, clan smallint, gabarit varchar(8), revenu integer, pm smallint, berserk boolean, tutelaire smallint, ere varchar(10), cyclope boolean); CREATE TABLE CREATE EXTENSION IF NOT EXISTS "uuid-ossp"; CREATE EXTENSION WITH serie(i) AS (SELECT generate_series(55000000,100001,-1)) insert into geants select uuid_generate_v4(), current_date - (ceil(i/3) || ' minutes')::interval + (trunc(random() * 100 + 1) || ' days')::interval, case when random() < 0.45 then 'M' else 'F' end, 200 + (trunc(random() * 200 + 1)), 300 + (trunc(random() * 200 + 1)), case when random() < 0.7 then false else true end, upper(md5(random()::text)), (trunc(random()*100 + 1)), case when random() < 0.1 then false else true end, case when random() < 0.7 then 'GRIS' when random() < 0.8 then 'NOIR' else 'BLEU' end, case when random() < 0.9 then false else true end, (trunc(random()*1000 + 1)), case when random() < 0.1 then 'PETIT' when random() < 0.9 then 'MOYEN' else 'GRAND' end, (trunc(random()*1000000 + 1)), (trunc(random()*10 + 1)), case when random() < 0.01 then true else false end, (trunc(random()*10 + 1)), case when i < 18000000 then 'TAUREAU' when i < 40000000 then 'LICORNE' else 'DRAGON' end, case when random() < 0.001 then true else false end from serie; INSERT 0 54900000 analyze geants; ANALYZE \d+ Liste des relations Schéma | Nom | Type | Propriétaire | Taille | Description --------+--------+-------+--------------+---------+------------- public | geants | table | postgres | 7033 MB | select avg(taille) filter (where genre = 'M') taille_moyenne_geants, avg(taille) filter (where genre = 'F') taille_moyenne_geantes, avg(masse) filter (where actif) masse_moyenne_actifs, avg(masse) filter (where not actif) masse_moyenne_blesses, count(*) filter (where revenu > 900000) nombre_riches, count(*) filter (where berserk and veteran) nombre_guerriers_fous from geants; Time: 83220,133 ms (01:23,220) show work_mem; work_mem ---------- 4MB (1 ligne) show shared_buffers; shared_buffers ---------------- 128MB (1 ligne) cat /proc/meminfo | grep MemTotal MemTotal: 501344 kB ./traqueur.sh -p traqueur 0.06.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 | blocker | non_cpu_pc | mem_en_mo | swapped_en_mo ---------+--------------+----------+-----+----------+-----------+-------------+-----------------------------------------------------------+-----------------+---------+------------+-----------+--------------- 74 | 1 / 37 | postgres | 631 | postgres | | psql | select +| IO | | 67 | | | | | | | | | avg(taille) filter (where genre = 'M') taille_moyenne_ge | | | | | 70 | 1 / 35 | postgres | 633 | postgres | | psql | select +| IO | | 65 | | | | | | | | | avg(taille) filter (where genre = 'M') taille_moyenne_ge | | | | | 68 | 1 / 34 | postgres | 634 | postgres | | psql | select +| IO | | 66 | | | | | | | | | avg(taille) filter (where genre = 'M') taille_moyenne_ge | | | | | 32 | 1 / 16 | postgres | 634 | postgres | | psql | select +| | | 66 | 1 | 0 | | | | | | | avg(taille) filter (where genre = 'M') taille_moyenne_ge | | | | | 30 | 1 / 15 | postgres | 633 | postgres | | psql | select +| | | 70 | 1 | 0 | | | | | | | avg(taille) filter (where genre = 'M') taille_moyenne_ge | | | | | 26 | 1 / 13 | postgres | 631 | postgres | | psql | select +| | | 70 | 1 | 0 | | | | | | | avg(taille) filter (where genre = 'M') taille_moyenne_ge | | | | | (6 lignes) Charge CPU moyennne globale ----------------------------- 12 (1 ligne) temps_cpu_user_en_s | temps_cpu_systeme_en_s | temps_cpu_idle_en_s | temps_io_en_s ---------------------+------------------------+---------------------+--------------- 5 | 1 | 26 | 10 (1 ligne) ./traqueur.sh -p -o "query, wait_event_type" traqueur 0.06.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 | query | wait_event_type | non_cpu_pc | mem_en_mo | swapped_en_mo ---------+--------------+--------------------------------------------------------------------+-----------------+------------+-----------+--------------- 216 | 3 / 108 | select +| IO | 62 | 1 | 0 | | avg(taille) filter (where genre = 'M') taille_moyenne_geants, +| | | | | | avg(taille) filter (where genre = 'F') taille_moyenne_geantes, +| | | | | | avg(masse) filter (where actif) masse_moyenne_actifs, +| | | | | | avg(masse) filter (where not actif) masse_moyenne_blesses, +| | | | | | count(*) filter (where revenu > 900000) nombre_riches, +| | | | | | count(*) filter (where berserk and veteran) nombre_guerriers_fous+| | | | | | from geants; | | | | 84 | 3 / 42 | select +| | 59 | | | | avg(taille) filter (where genre = 'M') taille_moyenne_geants, +| | | | | | avg(taille) filter (where genre = 'F') taille_moyenne_geantes, +| | | | | | avg(masse) filter (where actif) masse_moyenne_actifs, +| | | | | | avg(masse) filter (where not actif) masse_moyenne_blesses, +| | | | | | count(*) filter (where revenu > 900000) nombre_riches, +| | | | | | count(*) filter (where berserk and veteran) nombre_guerriers_fous+| | | | | | from geants; | | | | (2 lignes) Charge CPU moyennne globale ----------------------------- 14 (1 ligne) temps_cpu_user_en_s | temps_cpu_systeme_en_s | temps_cpu_idle_en_s | temps_io_en_s ---------------------+------------------------+---------------------+--------------- 5 | 1 | 25 | 9 (1 ligne)

IO peut être vache

      Nous constatons d’abord que 3 process distincts traitent la requête, le nombre de travailleurs pouvant prêter main forte pour l’exécution d’une requête étant de 2 par défaut avec PostgreSQL 10.
      Cependant, ce n’est pas l’aspect le plus important dans cet atelier. N’oubliez pas de toute façon qu’avec l’option -o vous pouvez agréger comme vous le souhaitez les résultats ainsi que le montre la 2ème exécution du traqueur.
      Je vous ai en fait donné le nom de l’assassin avant la fin du film. La table fait 7Go. La RAM de ma VM fait 500Mo et ne peut en aucun cas permettre de mettre en cache les données de toute la table. Hors, la requête qui dure 83s nécessite de balayer toute la table. Logiquement, nous retrouvons donc en tête de l’activité l’événement IO.
      La colonne non_cpu_pc n’est qu’une indication. Elle est calculée à partir des informations remontées via le module psutil de python. La valeur est déterminée en évaluant le pourcentage CPU pendant 1/10ème de seconde pour chaque process détecté comme actif. La précision est donc faible, surtout sur une petite durée de traque.
      Ici, nous constatons cependant que nous faisons plutôt du "non CPU". Cela signifie que les I/O sont de "vraies" I/O et non des I/O réalisées via le cache du système d’exploitation.
      Au niveau des temps d’attente obtenus globalement au niveau du serveur, nous constatons que nous avons 9 ou 10s de temps d’attente I/O par session de traque et que la charge CPU globale est faible : 12 à 14%. Je suis seul à travailler sur ce système comprenant 8 processeurs donc ce chiffre pourrait monter à 36-37%. Ne pas réussir à faire travailler les processeurs n’est PAS un bon signe !
      A présent, nous allons muscler le serveur en mémoire vive et réaliser une 2ème session de traque :

cat /proc/meminfo | grep MemTotal MemTotal: 32885008 kB select avg(taille) filter (where genre = 'M') taille_moyenne_geants, avg(taille) filter (where genre = 'F') taille_moyenne_geantes, avg(masse) filter (where actif) masse_moyenne_actifs, avg(masse) filter (where not actif) masse_moyenne_blesses, count(*) filter (where revenu > 900000) nombre_riches, count(*) filter (where berserk and veteran) nombre_guerriers_fous from geants; taille_moyenne_geants | taille_moyenne_geantes | masse_moyenne_actifs | masse_moyenne_blesses | nombre_riches | nombre_guerriers_fous -----------------------+------------------------+----------------------+-----------------------+---------------+----------------------- 300.4958258932471955 | 300.4937161641648053 | 400.4726003940800149 | 400.5138511709099279 | 5489813 | 55849 (1 ligne) Time: 16603,606 ms (00:16,604) ./traqueur.sh -p traqueur 0.06.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 | blocker | non_cpu_pc | mem_en_mo | swapped_en_mo ---------+--------------+----------+-----+----------+-----------+-------------+-----------------------------------------------------------+-----------------+---------+------------+-----------+--------------- 94 | 1 / 47 | postgres | 711 | postgres | | psql | select +| | | 0 | 1 | 0 | | | | | | | avg(taille) filter (where genre = 'M') taille_moyenne_ge | | | | | 92 | 1 / 46 | postgres | 631 | postgres | | psql | select +| | | -0 | | | | | | | | | avg(taille) filter (where genre = 'M') taille_moyenne_ge | | | | | 88 | 1 / 44 | postgres | 712 | postgres | | psql | select +| | | 1 | 1 | 0 | | | | | | | avg(taille) filter (where genre = 'M') taille_moyenne_ge | | | | | 12 | 1 / 6 | postgres | 712 | postgres | | psql | select +| IO | | 1 | | | | | | | | | avg(taille) filter (where genre = 'M') taille_moyenne_ge | | | | | 8 | 1 / 4 | postgres | 631 | postgres | | psql | select +| IO | | -4 | 1 | 0 | | | | | | | avg(taille) filter (where genre = 'M') taille_moyenne_ge | | | | | 6 | 1 / 3 | postgres | 711 | postgres | | psql | select +| IO | | -2 | | | | | | | | | avg(taille) filter (where genre = 'M') taille_moyenne_ge | | | | | (6 lignes) Charge CPU moyennne globale ----------------------------- 37 (1 ligne) temps_cpu_user_en_s | temps_cpu_systeme_en_s | temps_cpu_idle_en_s | temps_io_en_s ---------------------+------------------------+---------------------+--------------- 14 | 2 | 25 | 0 (1 ligne)

IO peut être discrète

      La requête a duré 16s6. Le type d’événement IO n’est plus en tête de l’activité. Il existe des moyens de savoir si une I/O provient du cache OS ou non mais pg_stat_activity ne vous donnera pas cette information. Ici c’est la colonne non_cpu_pc qui va nous donner le tuyau. En effet, au contraire de ce que nous avons observé dans la 1ère session de traque, la valeur dans la colonne non_cpu_pc est toujours proche de 0 donc toute l’activité est sur le CPU.
      Ces I/O sont trop rapides pour provenir du sous-système de stockage. La table pg_stat_activity indique comme type d’événement d’attente "IO" mais nous pouvons conclure ici que les données proviennent du cache du système d’exploitation.
      Je suis toujours seul à travailler sur le serveur et nous pouvons constater au niveau de la charge globale du serveur que le temps I/O est de 0s alors que la charge CPU est à 37%. Chacun des process exécutant la requête a donc réussi à faire travailler à 100% un coeur de CPU.
      La machine est plus chargée au niveau CPU ... mais c’est ici un BON signe.
      Nous allons enfin dimensionner le cache de PostgreSQL de manière à ce qu’il puisse accueillir toutes les données de la table en augmentant la valeur de shared_buffers à 24Go et réaliser une 3ème session de traque :

alter system set shared_buffers="24GB"; ALTER SYSTEM pg_ctlcluster 10 main restart create extension pg_prewarm; CREATE EXTENSION select pg_prewarm('geants'); pg_prewarm ------------ 900000 select avg(taille) filter (where genre = 'M') taille_moyenne_geants, avg(taille) filter (where genre = 'F') taille_moyenne_geantes, avg(masse) filter (where actif) masse_moyenne_actifs, avg(masse) filter (where not actif) masse_moyenne_blesses, count(*) filter (where revenu > 900000) nombre_riches, count(*) filter (where berserk and veteran) nombre_guerriers_fous from geants; taille_moyenne_geants | taille_moyenne_geantes | masse_moyenne_actifs | masse_moyenne_blesses | nombre_riches | nombre_guerriers_fous -----------------------+------------------------+----------------------+-----------------------+---------------+----------------------- 300.4958258932471955 | 300.4937161641648053 | 400.4726003940800149 | 400.5138511709099279 | 5489813 | 55849 (1 ligne) Time: 16363,760 ms (00:16,364) ./traqueur.sh -p traqueur 0.06.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 | blocker | non_cpu_pc | mem_en_mo | swapped_en_mo ---------+--------------+----------+------+----------+-----------+-------------+-----------------------------------------------------------+-----------------+---------+------------+-----------+--------------- 100 | 1 / 50 | postgres | 997 | postgres | | psql | select +| | | -1 | 2 | 0 | | | | | | | avg(taille) filter (where genre = 'M') taille_moyenne_ge | | | | | 100 | 1 / 50 | postgres | 1001 | postgres | | psql | select +| | | 1 | 0 | 0 | | | | | | | avg(taille) filter (where genre = 'M') taille_moyenne_ge | | | | | 100 | 1 / 50 | postgres | 1002 | postgres | | psql | select +| | | 0 | 0 | 0 | | | | | | | avg(taille) filter (where genre = 'M') taille_moyenne_ge | | | | | (3 lignes) Charge CPU moyennne globale ----------------------------- 38 (1 ligne) temps_cpu_user_en_s | temps_cpu_systeme_en_s | temps_cpu_idle_en_s | temps_io_en_s ---------------------+------------------------+---------------------+--------------- 14 | 2 | 25 | 0 (1 ligne)

IO peut disparaître

      Durée de 16s3 et plus d’événement de type IO. PostgreSQL ne considère pas l’accès aux données présentes dans son cache comme des I/O et considère qu’il n’attend rien du tout. Chacun des 3 process exécutant en parallèle la requête a ce qu’il faut pour travailler et il fonce, utilisant un coeur de CPU à 100% pendant la session de traque.
      Ces informations sont cohérentes avec les informations globales, sachant que je suis seul à travailler sur la machine bien sûr. Comme dans la 2ème session de traque, nous ne constatons aucun temps d’attente I/O sur la machine et une charge CPU globale similaire (38% contre 37%)

Conclusion

      pg_stat_activity présente toujours plus d’informations précieuses pour optimiser et le traqueur vous permet d’en bénéficier de manière très simple. PostgreSQL 10 est encore en beta mais cette version est décidément très prometteuse.

Mise à jour : 20/06/2017