Traqueur, latence I/O vue de PostgreSQL

Un grand classique du diagnostic de performance

Téléchargement du traqueur pour PostgreSQL 12, 13, 14, 15, 16, 17
Téléchargement du traqueur pour PostgreSQL 11
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

      Chaque version de PostgreSQL apporte des avancées majeures. La version 16 ne fait pas exception. Dans cette version, il est plus facile de diagnostiquer les problèmes I/O que dans les versions précédentes. Certes, il était bien sûr déjà possible depuis longtemps d'identifier indirectement un problème I/O , comme le montre cet exemple avec PostgreSQL 10. Il était aussi possible de mesurer la latence avec un outil tiers comme Bonnie++. Mais une nouvelle vue, pg_stat_io, donne à présent directement l'information nécessaire pour mesurer les latences I/O si le paramètre d'initialisation track_io_timing est positionné sur "on" (il est à "off" par défaut). Positionnez le sur "on" le temps d'un diagnostic si vous soupçonnez un problème de latence, ou de façon permanente après avoir mesuré son impact sur votre plateforme.
      Le traqueur tire partie de cette nouvelle fonctionnalité de PostgreSQL 16 depuis sa version 7. Si track_io_timing est à "on", les données de pg_stat_io sont historisées en mode batch (option -b). Vous pouvez les afficher avec l'option -l dans les rapports produits avec l'option -r. Il est aussi possible de diagnostiquer en interactif directement avec l'option -l.
      Premier exemple dans une situation saine avec une grosse insertion de données sur mon PC portable et son stockage SSD/NVMe :

select version(); version ------------------------------------------------------------------------------------------------------------------------ PostgreSQL 16rc1 (Debian 16~rc1-1.pgdg120+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 12.2.0-14) 12.2.0, 64-bit (1 ligne) alter system set track_io_timing = on; ALTER SYSTEM select pg_reload_conf(); pg_reload_conf ---------------- t (1 ligne) 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 \timing WITH serie(i) AS (SELECT generate_series(11000000,1000001,-1)) insert into geants select gen_random_uuid(), 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 10000000 Durée : 69453,129 ms (01:09,453) -- simultanement time ./traqueur.sh -l -d 60 traqueur 7.00.00 - https://pgphil.ovh - outil de diagnostic performance pour PostgreSQL 11 => 16 INFORMATION, pas de base de connexion indiquee, utilisation de la base dediee detectee ... INFORMATION, connecte a la base traqueur INFORMATION, version de PostgreSQL detectee : 160000 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 ---------+--------------+----------+-------+----------+-----------+-------------+-----------------------------------------------------------------+-----------------+---------- 38 | 1 / 225 | postgres | 89636 | postgres | | psql | WITH serie(i) AS (SELECT generate_series(11000000,1000001,-1)) +| | | | | | | | | | | 3 | 1 / 18 | postgres | 89636 | postgres | | psql | WITH serie(i) AS (SELECT generate_series(11000000,1000001,-1)) +| IO | | | | | | | | | | 2 | 1 / 12 | postgres | 89636 | postgres | | psql | WITH serie(i) AS (SELECT generate_series(11000000,1000001,-1)) +| LWLock | | | | | | | | | | (3 lignes) Contexte | Latence lectures | Latence ecritures | Latence ecritures permanentes | Latence extensions fichiers | Latence fsyncs | Evictions -----------+------------------+-------------------+-------------------------------+-----------------------------+----------------+----------- bulkread | | | | | | 0 bulkwrite | | | | | | 0 normal | 0.01 | 0.00 | 0.01 | 0.01 | 7.62 | 2112 vacuum | 0.00 | 0.00 | | | | 36 (4 lignes) real 1m0,534s user 0m0,168s sys 0m0,035s -- a posteriori ./traqueur.sh -r -l traqueur 7.00.00 - https://pgphil.ovh - outil de diagnostic performance pour PostgreSQL 11 => 16 INFORMATION, pas de base de connexion indiquee, utilisation de la base dediee detectee ... INFORMATION, connecte a la base traqueur INFORMATION, version de PostgreSQL detectee : 160000 INFORMATION, production d'un rapport depuis les informations collectees par le traqueur en mode batch ... Variable TRAQUEUR_RAPPORT_DEBUT non renseignee, indiquez la borne de temps inferieure, par defaut : current_timestamp - interval '15 minutes' current_timestamp - interval '5 minutes' Variable TRAQUEUR_RAPPORT_FIN non renseignee, indiquez la borne de temps superieure, par defaut : current_timestamp Variable TRAQUEUR_RAPPORT_TOP_N non renseignee, indiquez le nombre d'elements pour les tops evenements et requetes, par defaut : 5 Variable TRAQUEUR_RAPPORT_FILTRE non renseignee, indiquez les options de filtrage pour les tops requetes et applications, par defaut : application_name <> 'traqueur' and backend_type <> 'autovacuum worker' and backend_type <> 'walsender' Variable TRAQUEUR_RAPPORT_FORMAT non renseignee, indiquez le format du rapport (aligned pour obtenir du texte ou html), par defaut : aligned Variable TRAQUEUR_RAPPORT_NOM non renseignee, indiquez le chemin et le nom du fichier du rapport, par defaut : /tmp/rapport_traqueur_89848.txt (ou /tmp/rapport_traqueur_89848.htm si le format est html) postgres@astuf:/tmp$ cat /tmp/rapport_traqueur_89848.txt RAPPORT DU TRAQUEUR Nom du serveur ---------------- astuf Borne inferieure | Borne superieure ---------------------+--------------------- 02/09/2023 17:05:48 | 02/09/2023 17:06:18 - Latence I/O (en millisecondes) et evictions du cache - Contexte | Latence lectures | Latence ecritures | Latence ecritures permanentes | Latence extensions fichiers | Latence fsyncs | Evictions -----------+------------------+-------------------+-------------------------------+-----------------------------+----------------+----------- bulkread | | | | | | 0 bulkwrite | | | | | | 0 normal | 0.01 | 0.00 | 0.00 | 0.01 | 7.62 | 9096 vacuum | 0.02 | 0.00 | | | | 228 ...

      Un peu plus d'une minute pour insérer les 10 millions de lignes. La latence relevée, à la fois en interactif et dans le rapport, est proche de 0, sauf pour les fsyncs où elle est plus élevée mais reste sous les 10ms.
      A présent le même test mais le cluster est créé sur une clé USB :

WITH serie(i) AS (SELECT generate_series(11000000,1000001,-1)) insert into geants select gen_random_uuid(), 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 10000000 Durée : 8385285,260 ms (02:19:45,285) -- simultanement time ./traqueur.sh -l -d 60 traqueur 7.00.00 - https://pgphil.ovh - outil de diagnostic performance pour PostgreSQL 11 => 16 INFORMATION, pas de base de connexion indiquee, utilisation de la base dediee detectee ... INFORMATION, connecte a la base traqueur INFORMATION, version de PostgreSQL detectee : 160000 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 ---------+--------------+----------+-------+----------+-----------+-------------+-----------------------------------------------------------------+-----------------+---------- 66 | 1 / 398 | postgres | 80098 | postgres | | psql | WITH serie(i) AS (SELECT generate_series(11000000,1000001,-1)) +| LWLock | | | | | | | | | | 42 | 1 / 249 | traqueur | 80128 | postgres | | traqueur | call pg_temp.traqueur_collection(); | LWLock | 33 | 1 / 197 | postgres | 80098 | postgres | | psql | WITH serie(i) AS (SELECT generate_series(11000000,1000001,-1)) +| IO | | | | | | | | | | 1 | 1 / 5 | postgres | 80098 | postgres | | psql | WITH serie(i) AS (SELECT generate_series(11000000,1000001,-1)) +| | | | | | | | | | | (4 lignes) Contexte | Latence lectures | Latence ecritures | Latence ecritures permanentes | Latence extensions fichiers | Latence fsyncs | Evictions -----------+------------------+-------------------+-------------------------------+-----------------------------+----------------+----------- bulkread | | | | | | 0 bulkwrite | | | | | | 0 normal | | 135.44 | 322.67 | | | 0 vacuum | | | | | | 0 (4 lignes) real 4m18,814s user 0m0,189s sys 0m0,032s -- a posteriori ./traqueur.sh -r -l traqueur 7.00.00 - https://pgphil.ovh - outil de diagnostic performance pour PostgreSQL 11 => 16 INFORMATION, pas de base de connexion indiquee, utilisation de la base dediee detectee ... INFORMATION, connecte a la base traqueur INFORMATION, version de PostgreSQL detectee : 160000 INFORMATION, production d'un rapport depuis les informations collectees par le traqueur en mode batch ... Variable TRAQUEUR_RAPPORT_DEBUT non renseignee, indiquez la borne de temps inferieure, par defaut : current_timestamp - interval '15 minutes' current_timestamp - interval '120 minutes' Variable TRAQUEUR_RAPPORT_FIN non renseignee, indiquez la borne de temps superieure, par defaut : current_timestamp current_timestamp - interval '60 minutes' Variable TRAQUEUR_RAPPORT_TOP_N non renseignee, indiquez le nombre d'elements pour les tops evenements et requetes, par defaut : 5 Variable TRAQUEUR_RAPPORT_FILTRE non renseignee, indiquez les options de filtrage pour les tops requetes et applications, par defaut : application_name <> 'traqueur' and backend_type <> 'autovacuum worker' and backend_type <> 'walsender' Variable TRAQUEUR_RAPPORT_FORMAT non renseignee, indiquez le format du rapport (aligned pour obtenir du texte ou html), par defaut : aligned Variable TRAQUEUR_RAPPORT_NOM non renseignee, indiquez le chemin et le nom du fichier du rapport, par defaut : /tmp/rapport_traqueur_88688.txt (ou /tmp/rapport_traqueur_88688.htm si le format est html) cat /tmp/rapport_traqueur_88688.txt RAPPORT DU TRAQUEUR Nom du serveur ---------------- astuf Borne inferieure | Borne superieure ---------------------+--------------------- 02/09/2023 14:49:28 | 02/09/2023 15:49:02 - Latence I/O (en millisecondes) et evictions du cache - Contexte | Latence lectures | Latence ecritures | Latence ecritures permanentes | Latence extensions fichiers | Latence fsyncs | Evictions -----------+------------------+-------------------+-------------------------------+-----------------------------+----------------+----------- bulkread | | | | | | 0 bulkwrite | | | | | | 0 normal | 25.56 | 19.43 | 134.51 | 132.62 | 4016.40 | 11640 vacuum | 92.96 | 0.01 | | | | 270 ...

      C'est évidemment une catastrophe, le temps pour effectuer l'insert passe à plus de 2 heures. L'exécution du traqueur en interactif, censée durer une minute, en prend plus de quatre. En interactif comme dans le rapport, le traqueur permet de mettre des chiffres sur cette catastrophe. C'est bien simple : la latence explose.

Conclusion

      La vue pg_stat_io est un nouveau point d'entrée très efficace pour diagnostiquer un problème de performance I/O, directement depuis PostgreSQL. Ici, je l'ai exploitée via mon outil personnel, le traqueur, mais nul doute que les autres outils de performance PostgreSQL vont en tirer parti également. Cette vue permet en effet d'obtenir une information sur les latences en lecture/écriture, équivalente à celle obtenue dans les rapports statspack ou AWR bien connus des DBA Oracle .
      Merci au PostgreSQL Global Development Group, et notamment ici à Melanie Plageman, de faciliter toujours davantage la vie des DBA PostgreSQL.

Mise à jour : 02/09/2023