Suivre des traces dans PostgreSQL
Cet article propose de mettre en œuvre des scripts de traçage de
l’exécution de PostgreSQL, via l’outil SystemTap.
L’intérêt de l’exercice est de pouvoir observer le fonctionnement d’une
instance PostgreSQL sans modifier sa configuration, sans devoir
l’exécuter d’une manière particulière, ni modifier les logiciels
utilisant l’instance PostgreSQL.
PostgreSQL a ajouté dans son code source des marqueurs qui permettent
le suivi de l’exécution depuis SystemTap ou DTrace, et nous allons
donc pouvoir les utiliser dans des scripts SystemTap. La liste des
marqueurs est documentée et disponible à l’adresse suivante :
https://www.postgresql.org/docs/devel/static/dynamic-trace.html.
Qu’est-ce que SystemTap ?
SystemTap est un outil permettant l’instrumentation d’un noyau Linux
en cours de fonctionnement. SystemTap dispose d’un langage de script
permettant la compilation de modules chargeables dans le noyau Linux.
La commande stap, fournie par SystemTap, permet de traiter
l’ensemble des tâches nécessaires, de la compilation au suivi de
l’exécution, en passant par le chargement du module dans le noyau.
Le langage de script est lui-même documenté à l’adresse suivante :
https://sourceware.org/systemtap/langref/langref.html.
L’imbrication des composants est telle qu’il n’est pas recommandé de
faire cela sur un système de production, mais plutôt de réserver ce
suivi dans le cadre d’un environnement de tests.
Comme dans bien des domaines : « on modifie ce qu’on observe » !
Attention donc à ce qu’on modifie en observant.
Installation
SystemTap n’est pas livré avec le noyau, et suit son propre cycle de
développement.
Il est donc nécessaire d’installer SystemTap.
De plus,
pour la compilation des modules chargeables dans le noyau Linux, les
fichiers d’entête du noyau sont nécessaires.
Le système utilisé pour l’exercice est Debian GNU/Linux Jessie, soit
la version stable à l’heure où cet article est écrit. Mais la version
de SystemTap est trop ancienne pour être utilisée, et la dernière
version, 3.1, n’est pas encore disponible dans le dépôt
jessie-backports ; nous allons donc compiler ce portage.
Les commandes suivantes installent les paquets Debian nécessaires :
- pour la compilation de SystemTap
- pour l’exécution des scripts SystemTap
Installation des paquets Debian
La commande suivante installe une version récente du noyau Linux, avec
ses fichiers d’entête, depuis le dépôt jessie-backports qui doit
donc être activé dans le système utilisé :
apt-get install linux-image-4.9.0-0.bpo.2-amd64 linux-headers-4.9.0-0.bpo.2-amd64
Compilation du paquet SystemTap
Les commandes suivantes récupèrent les sources de la dernière version
de SystemTap, disponible dans de dépôt sid, puis compile et installe
cette version du paquet :
apt-get source -t sid systemtap
sudo apt-get build-dep systemtap
cd systemtap-3.1
dpkg-buildpackage -rfakeroot -b
sudo dpkg -i systemtap_3.1-2_amd64.deb systemtap-common_3.1-2_all.deb \
systemtap-runtime_3.1-2_amd64.deb systemtap-client_3.1-2_amd64.deb
À ce moment, si les dépendances ne sont pas toutes correctement
remplies, il convient de lancer la commande suivante :
apt-get -f install
Enfin, PostgreSQL doit être compilé avec les marqueurs dtrace
activée, ce qui n’est le cas par défaut.
Compilation de PostgreSQL
Les paquets Debian de PostgreSQL sont compilés sans l’option
--enable-dtrace, il n’est donc pas possible d’utiliser le paquet par
défaut pour tester SystemTap. À noter toutefois que les développeurs
des paquets Debian de PostgreSQL sont informés de ce manque, et l’ont
pris en compte,
il n’est pas impossible qu’à l’avenir, les paquets soient déjà prêts !
Les commandes suivantes compilent PostgreSQL et créent une instance pour le test :
wget https://ftp.postgresql.org/pub/source/v9.6.3/postgresql-9.6.3.tar.bz2
tar xf postgresql-9.6.3.tar.bz2
cd postgresql-9.6.3
./configure --prefix=/usr/local/pgsql/ --enable-dtrace --enable-debug --with-pgport=5440
make -j4
cd contrib
make -j4
cd ..
sudo make install
cd contrib
sudo make install
Puis, Création d’un « cluster » et connexion :
export PATH=/usr/local/pgsql/bin:$PATH
initdb -D /var/lib/pgsql/data -A trust
pg_ctl -D /var/lib/pgsql/data start
psql
À ce moment, tout est prêt. Les premiers scripts SystemTap peuvent être lancés !
Note : Dans les systèmes RedHat et Centos, les paquets PostgreSQL sont
déjà prêts, et l’installation de SystemTap se fait sans difficulté via
le système de paquetages.
Premier script
Le premier script proposé montre les requêtes exécutées :
- une ligne écrite au démarrage ;
- une ligne à la fin de la requête, avec le temps d’exécution.
global livequeries
probe process("/usr/local/pgsql/bin/postgres").mark("query__start"){
printf("[%s] Query start on PID %d : %s \n", ctime(gettimeofday_s()), pid(), user_string($arg1) )
livequeries[tid(),$arg1] = gettimeofday_us()
}
probe process("/usr/local/pgsql/bin/postgres").mark("query__done"){
now=gettimeofday_us()
t=tid()
if([t,$arg1] in livequeries){
delta= now - livequeries[t,$arg1]
delete livequeries[t,$arg1]
}
printf("[%s] Query done on PID %d : %d us \n", ctime(gettimeofday_s()), pid(), delta )
}
L’instruction probe permet d’exécuter des instructions lorsque le
marqueur (query_start) est trouvé. La variable $arg1 contient un
pointeur vers le texte de la requête.
La fonction pid() permet de connaître l’identifiant du processus
système, et donc le processus ayant exécuté la requête.
À part la fonction servant à la sortie texte, le temps est ici mesuré
en microsecondes, ce qui est normalement suffisant dans ce contexte.
Ce script peut-être lancé avec un utilisateur suffisamment privilégié
pour charger le module :
stp -v queries.stp
Pass 1: parsed user script and 470 library scripts using 110480virt/43072res/5832shr/37652data kb, in 190usr/20sys/244real ms.
Pass 2: analyzed script: 2 probes, 10 functions, 4 embeds, 1 global using 112468virt/46724res/7488shr/39640data kb, in 10usr/60sys/78real ms.
Pass 3: using cached /home/slardiere/.systemtap/cache/8f/stap_8f19338d5a9e426cab5c0ebb26783ace_8079.c
Pass 4: using cached /home/slardiere/.systemtap/cache/8f/stap_8f19338d5a9e426cab5c0ebb26783ace_8079.ko
Pass 5: starting run.
[Fri May 26 13:32:22 2017] Query start on PID 30809 : select count(*) from generate_series(1, 5000);
[Fri May 26 13:32:22 2017] Query done on PID 30809 : 897 us
[Fri May 26 13:32:24 2017] Query start on PID 30809 : select 1;
[Fri May 26 13:32:24 2017] Query done on PID 30809 : 109 us
Les requêtes SQL ont été exécutées dans le client
psql connecté à l’instance préalablement démarrée.
Il est aisé de modifier ce script pour que la sortie ressemble à
un fichier de requêtes lentes, ce qui permet de les collecter sans
toucher à l’instance PostgreSQL existante.
Deuxième exemple : Mesure du temps
Le deuxième exemple tente de répondre à un problème régulièrement
rencontré : le temps passé dans une transaction à ne rien faire !
En effet, pendant une transaction, les verrous acquis par les requêtes
passées ne sont pas relâchés, et peuvent donc gêner les transactions
concurrentes.
Le script suivant mesure le temps passé dans une transaction, et le
temps passé par chacune des requêtes de la transaction, et en déduit
simplement le temps passé à ne rien faire, ce qui permet de se faire
une idée des possibilités d’améliorations des performances :
global tx
global queriescount
global queriestime
global queries
probe process("/usr/local/pgsql/bin/postgres").mark("transaction__start") {
printf("[%s] TX %d start: %d on CPU %d \n", ctime(gettimeofday_s()), $arg1, pid(), cpu())
tx[pid(),$arg1] = gettimeofday_us()
}
probe process("/usr/local/pgsql/bin/postgres").mark("query__start")
{
queriescount[pid()] += 1
queries[pid(),$arg1] = gettimeofday_us()
}
probe process("/usr/local/pgsql/bin/postgres").mark("query__done")
{
now=gettimeofday_us()
p = pid()
if([p,$arg1] in queries){
delta= now - queries[p,$arg1]
queriestime[p] += delta
delete queries[p,$arg1]
}
}
probe process("/usr/local/pgsql/bin/postgres").mark("transaction-commit") {
now=gettimeofday_us()
p=pid()
if([p,$arg1] in tx){
delta= now - tx[p,$arg1]
printf("[%s] TX %d done on CPU %d , PID %d ; Total Time : %d \n", ctime(gettimeofday_s()), $arg1, cpu(), pid(), delta )
if( queriescount[pid()] > 0 ){
printf("[%s] TX %d done ; Queries : %d ; Idle Time : %d ; Total Query Time : %d \n",
ctime(gettimeofday_s()), $arg1, queriescount[pid()], delta - queriestime[pid()],
queriestime[pid()] )
}
}
delete tx[p,$arg1]
delete queriescount[pid()]
delete queriestime[pid()]
}
Les marqueurs des transactions permettent de mesurer le temps total
des transactions, et ceux des requêtes alimentent les variables
globales qui sont utilisées à la fin de la transaction pour calculer
le temps passé à ne rien faire (”Idle Time”) :
stap -v transactions.stp
Pass 1: parsed user script and 470 library scripts using 110476virt/42968res/5728shr/37648data kb, in 170usr/20sys/248real ms.
Pass 2: analyzed script: 4 probes, 10 functions, 4 embeds, 4 globals using 112588virt/46820res/7524shr/39760data kb, in 10usr/70sys/75real ms.
Pass 3: translated to C into "/tmp/stap0lQXzV/stap_ea6e88206d7b06b42cc8d648e7c7bbe2_9920_src.c" using 112588virt/47012res/7716shr/39760data kb, in 0usr/40sys/39real ms.
Pass 4: compiled C into "stap_ea6e88206d7b06b42cc8d648e7c7bbe2_9920.ko" in 3710usr/300sys/4622real ms.
Pass 5: starting run.
[Fri May 26 13:47:09 2017] TX 15926 start: 30809 on CPU 3
[Fri May 26 13:47:19 2017] TX 15926 done on CPU 2 , PID 30809 ; Total Time : 9496108
[Fri May 26 13:47:19 2017] TX 15926 done ; Queries : 6 ; Idle Time : 9492539 ; Total Query Time : 3569
[Fri May 26 13:47:21 2017] TX 15927 start: 30809 on CPU 0
[Fri May 26 13:47:26 2017] TX 15927 done on CPU 1 , PID 30809 ; Total Time : 5368058
[Fri May 26 13:47:26 2017] TX 15927 done ; Queries : 7 ; Idle Time : 5363078 ; Total Query Time : 4980
Dans cet exemple, le temps passé a ne rien faire est volontairement
exagéré, mais sur une application normale, un temps trop élevé doit
alerter sur la gestion des transactions et le comportement de l’application.
Bien que la surveillance des transactions soit un point important des performances d’une instance
PostgreSQL, l’information précédente n’est pas disponible directement dans l’instance.
Conclusion
Ces deux exemples simples montrent la souplesse de l’outil, au prix
d’une mise en œuvre assez simple.
La réalisation de scripts plus élaborés est accessible à
un administrateur confronté à des problèmes de performance difficiles à
résoudre avec les outils internes à PostgreSQL.
Il s’agit donc d’un nouvel atout dans la boite à outils du DBA
PostgreSQL.
La plupart des systèmes d’exploitation optimisent les parcours de données en proposant une fenêtre de lecture en avance, cela permet de pré-charger des données dans le cache et ainsi les fournir plus rapidement aux applications. PostgreSQL contient plusieurs optimisations pour favoriser ce comportement au niveau système, et porte également une fonctionnalité similaire avec l’option 
Bah, oui, c'est quand même 1 an et demi de boulot acharné !
