Retour sur ma conférence au PGDay.FR 2025

Publié le 18/06/2025 par Guillaume Lelarge

Reviers, le 18 juin 2025

À la fin de ma conférence au PGDay.FR 2025, j’ai eu le plaisir d’avoir plusieurs questions et j’aimerais revenir principalement sur l’une d’elles, n’ayant malheureusement pas pu développer plus.

Conférence de Guillaume Lelarge au pgday.fr 2025

Flavio Gurgel, du site Le Bon Coin, a parlé du cas des sessions qui exécutent énormément de petites requêtes, extrêmement rapides, qui laissent croire que les processus ne font rien. Tracer les requêtes est souvent impossible car il y en a trop. Un DBA pourrait logiquement penser qu’aucune requête n’est exécutée, mais la consommation CPU est pourtant bien là.

Ma réponse a été assez basique :

  • utiliser pg_stat_statements (page de référence) pour dénombrer les requêtes exécutées (plus exactement leur nombre avec la colonne calls) ;
  • récupérer périodiquement la valeur des colonnes xact_commit et xact_rollback de pg_stat_database (page de référence)… Si des requêtes sont exécutées, leurs valeurs devraient augmenter assez rapidement.

La première méthode n’est pas nécessairement exhaustive car cette extension ne garde en mémoire qu’un nombre limité (configurable) de requêtes particulièrement fréquentes. La deuxième méthode montre l’activité en terme de transactions, et non pas en terme de requêtes. Donc pas très satisfaisant.

Bien que ces réponses soient valides, il y a mieux à faire. Après être rentré, mon collègue Nicolas Gollet est venu me voir avec une idée : récupérer l’appel système execve pour décompter le nombre de sessions ouvertes. Idée intéressante mais ça n’indique que l’ouverture de session. Ceci m’a rappelé un outil que j’avais beaucoup testé l’année dernière, et qui pourrait répondre de plusieurs façons à la demande de Flavio.

Cet outil, c’est bpftrace. Pour le décrire très rapidement (et donc aussi un peu mal), bpftrace intercepte les appels de fonctions systèmes et utilisateurs pour exécuter du code supplémentaire. Il utilise un langage ressemblant à awk : s’il détecte tel motif (pour awk dans une chaîne de texte, pour bpftrace dans le nom d’une fonction), il exécute un code source. Comme pour awk, cela peut être un code très complexe. Bref, je ne vais pas faire un cours de bpftrace ici, ce n’est pas le sujet de cet article (cela étant dit, c’est possible dans un autre article si ça intéresse quelques-uns, et ça pourrait même faire un sujet de conférence pour un meetup, n’est-ce pas Sébastien :)) mais je vais présenter quatre petits programmes bpftrace qui répondent de différentes façons à la question de Flavio.

Commençons par une information qui risque de fâcher. Il faut être root pour exécuter bpftrace. Désolé.

Tous les exemples de script ci-dessous sont à enregistrer dans un fichier et à exécuter avec la commande suivante en tant que root :

bpftrace chemin/vers/fichier

Les scripts concernent une version 18 beta 1 de PostgreSQL installée via les paquets de la communauté. Il convient de remplacer le chemin vers le binaire postgres (donc remplacer /usr/pgsql-18/bin/postgres par le chemin complet vers votre binaire). Ces scripts fonctionneront probablement avec les versions précédentes de PostgreSQL.

Script de récupération des connexions

Ce script intercepte l’appel à la fonction InitPostgres() (code source) et en profite pour afficher un message à chaque exécution de la fonction contenant le nom de l’utilisateur se connectant (troisième argument de la fonction) et le nom de la base (premier argument de la fonction). Voici à quoi ressemble ce script :

uprobe:/usr/pgsql-18/bin/postgres:InitPostgres
{
  printf("connexion de l'utilisateur %s sur la base %s\n", str(arg2), str(arg0));
}

Et voici le résultat de son exécution :

$ sudo bpftrace connexions.bt
Attaching 1 probe...
connexion de l'utilisateur postgres sur la base benchs
connexion de l'utilisateur u1 sur la base b1
connexion de l'utilisateur postgres sur la base postgres
connexion de l'utilisateur postgres sur la base benchs
connexion de l'utilisateur postgres sur la base benchs
connexion de l'utilisateur postgres sur la base benchs

Script de récupération des requêtes

Maintenant, essayons de récupérer l’exécution d’une requête. Il existe une fonction, appelée exec_simple_query() (code source), qui fait exactement cela (j’explique plus bas pourquoi le « simple »).

Voici un script pour intercepter l’exécution des requêtes et afficher le PID du processus serveur et la requête exécutée :

BEGIN
{
  printf("En attente des requêtes…\n");
}

uprobe:/usr/pgsql-18/bin/postgres:exec_simple_query
{
  printf("PID %d - REQUÊTE %s\n", pid, str(arg0));
}

Avec un pgbench lancé sur un autre terminal, le script affiche rapidement des lignes indiquant le PID qui exécute la requête et la requête exécutée :

$ sudo bpftrace requetes1.bt
Attaching 2 probes...
En attente des requêtes…
PID 433109 - REQUÊTE select count(*) from pgbench_branches
PID 433109 - REQUÊTE select o.n, p.partstrat, pg_catalog.count(i.inhparent) from pg_catalog.pg_class as c join pg_catalog.pg_namespace as n on (n.oid = c.relnamespace) cross join lateral (select pg_catalog.array_position(pg_catalog.current_schemas(true), n.nspname)) as o(n) left join pg_catalog.pg_partitioned_table as p on (p.partrelid = c.oid) left join pg_catalog.pg_inherits as i on (c.oid = i.inhparent) where c.relname = 'pgbench_accounts' and o.n is not null group by 1, 2 order by 1 asc limit 1
PID 433109 - REQUÊTE vacuum pgbench_branches
PID 433109 - REQUÊTE vacuum pgbench_tellers
PID 433109 - REQUÊTE truncate pgbench_history
PID 433111 - REQUÊTE BEGIN;
PID 433110 - REQUÊTE BEGIN;
PID 433111 - REQUÊTE UPDATE pgbench_accounts SET abalance = abalance + -4236 WHERE aid = 3145341;
PID 433110 - REQUÊTE UPDATE pgbench_accounts SET abalance = abalance + -1157 WHERE aid = 1875583;
PID 433110 - REQUÊTE SELECT abalance FROM pgbench_accounts WHERE aid = 1875583;
PID 433111 - REQUÊTE SELECT abalance FROM pgbench_accounts WHERE aid = 3145341;
PID 433110 - REQUÊTE UPDATE pgbench_tellers SET tbalance = tbalance + -1157 WHERE tid = 431;
PID 433111 - REQUÊTE UPDATE pgbench_tellers SET tbalance = tbalance + -4236 WHERE tid = 892;
PID 433110 - REQUÊTE UPDATE pgbench_branches SET bbalance = bbalance + -1157 WHERE bid = 71;
PID 433111 - REQUÊTE UPDATE pgbench_branches SET bbalance = bbalance + -4236 WHERE bid = 82;
PID 433110 - REQUÊTE INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (431, 71, 1875583, -1157, CURRENT_TIMESTAMP);
PID 433111 - REQUÊTE INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (892, 82, 3145341, -4236, CURRENT_TIMESTAMP);
PID 433110 - REQUÊTE END;
PID 433111 - REQUÊTE END;

On a notre propre système de traces des requêtes !

Attention, ce script se base sur la fonction exec_simple_query(), qui lui-même se base sur le protocole de requêtes simples. Dans ce cas, il n’est pas possible de récupérer les requêtes préparées notamment. Un exemple avec un pgbench exécuté avec l’option -M prepared :

PID 435520 - REQUÊTE select count(*) from pgbench_branches
PID 435520 - REQUÊTE select o.n, p.partstrat, pg_catalog.count(i.inhparent) from pg_catalog.pg_class as c join pg_catalog.pg_namespace as n on (n.oid = c.relnamespace) cross join lateral (select pg_catalog.array_position(pg_catalog.current_schemas(true), n.nspname)) as o(n) left join pg_catalog.pg_partitioned_table as p on (p.partrelid = c.oid) left join pg_catalog.pg_inherits as i on (c.oid = i.inhparent) where c.relname = 'pgbench_accounts' and o.n is not null group by 1, 2 order by 1 asc limit 1
PID 435520 - REQUÊTE vacuum pgbench_branches
PID 435520 - REQUÊTE vacuum pgbench_tellers
PID 435520 - REQUÊTE truncate pgbench_history

Oopsie, il manque les SELECT, INSERT et autres UPDATE du scénario par défaut de pgbench.

Autrement dit, on récupère bien les requêtes simples, mais pas les requêtes préparées. Il faudrait donc écrire un script tenant compte du protocole étendu utilisé notamment par les requêtes préparées. L’écriture d’un tel script est laissé à l’exercice du lecteur afin de ne pas surcharger cet article, mais regardez du coté des fonctions :

Tout le jeu étant de conserver la dernière requête préparée pour chaque session et de l’afficher lors des appels à leur exécution.

Une autre possibilité plus simple est de compter les requêtes exécutées, ce qui simplifie grandement le script :

BEGIN
{
  printf("Comptage des requêtes en cours...\n");
  printf("Taper Ctrl-C pour obtenir le résultat.\n");
}

uprobe:/usr/pgsql-18/bin/postgres:exec_simple_query,
uprobe:/usr/pgsql-18/bin/postgres:exec_execute_message
{
  @ = count()
}

Voici le retour après l’écoute d’un pgbench exécuté avec l’option -M prepared :

$ sudo bpftrace query_count.bt
Attaching 3 probes...
Comptage des requêtes en cours…
Taper Ctrl-C pour obtenir le résultat.
@: 19

Nous retrouvons bien les 19 requêtes présentées lors du premier exemple.

Script d’histogramme des durées d’exécution des requêtes

Avoir le nombre de requêtes, c’est bien, mais avoir leur durée d’exécution, c’est mieux et ça donne l’occasion de donner un exemple un peu plus détaillé :

BEGIN
{
  printf("Comptage des requêtes et de leurs durées en cours…\n");
  printf("Taper Ctrl-C pour obtenir l'histogramme.\n");
}

uprobe:/usr/pgsql-18/bin/postgres:exec_simple_query,
uprobe:/usr/pgsql-18/bin/postgres:exec_execute_message
{
  @start[pid] = nsecs;
}

uretprobe:/usr/pgsql-18/bin/postgres:exec_simple_query,
uretprobe:/usr/pgsql-18/bin/postgres:exec_execute_message
{
  $duration_us = (nsecs - @start[pid]) / 1000;
  @us = hist($duration_us);
  delete(@start[pid]);
}

Et son résultat sur une plus grosse utilisation de pgbench :

$ sudo bpftrace requetes2.bt
Attaching 5 probes...
Comptage des requêtes et de leurs durées en cours…
Taper Ctrl-C pour obtenir l'histogramme.
@us:
[16, 32)             193 |                                                    |
[32, 64)           18123 |@@@                                                 |
[64, 128)         133549 |@@@@@@@@@@@@@@@@@@@@@@@@@@@                         |
[128, 256)        252891 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[256, 512)        118352 |@@@@@@@@@@@@@@@@@@@@@@@@                            |
[512, 1K)          16116 |@@@                                                 |
[1K, 2K)           35758 |@@@@@@@                                             |
[2K, 4K)           95873 |@@@@@@@@@@@@@@@@@@@                                 |
[4K, 8K)            2407 |                                                    |
[8K, 16K)            443 |                                                    |
[16K, 32K)             1 |                                                    |
[32K, 64K)            10 |                                                    |
[64K, 128K)            9 |                                                    |

L’intervalle en première colonne correspond à un intervalle de durée. Cet intervalle est en microsecondes. Le nombre en deuxième colonne est le nombre de requêtes compris dans cet intervalle de durées. Par exemple, il y a eu 133 549 requêtes dont la durée était comprise entre 64 et 128 microsecondes, et seulement neuf entre 64 et 128 ms.

Donc, dans cet exemple, la majorité des requêtes se sont exécutées entre 128 et 256 microsecondes. On en a quand même eu 20 prenant plus de 16 ms. Heureusement que c’est un test simple.

Voilà ce que j’aurais dû répondre à Flavio, mais cette réponse n’est pas venue suffisamment rapidement pendant le petit moment des questions :)

DALIBO

DALIBO est le spécialiste français de PostgreSQL®. Nous proposons du support, de la formation et du conseil depuis 2005.