LOXODATA

Suivre des traces dans PostgreSQL

2017-06-07   1485 mots, 7 minutes de lecture   Sébastien Lardière

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.