Tracer PostgreSQL avec perf

L'utilitaire de profilage perf qui est livré avec le noyau Linux est extrêmement utile pour examiner le comportement à l'échelle du système et multi-processus - mais il fait beaucoup plus que le profilage du processeur pour lequel il est souvent utilisé. Vous avez probablement regardé perf top -az ou perf top -u postgres sortie, mais ce n'est que la moindre partie de ce qu'il peut faire. (Si vous voulez la version TL/DR, passez à "Sondes dynamiques de l'espace utilisateur").

Un des gros avantages de perf c'est qu'il n'est pas intrusif. Vous n'avez pas besoin d'attacher un débogueur et d'interrompre l'exécution. Vous n'avez pas besoin d'exécuter des commandes directement sous un profileur dans un environnement spécial. Il n'est pas nécessaire de redémarrer le serveur pour déboguer une charge de travail problématique, et souvent pas besoin de recompiler avec les options de débogage. Ceci est extrêmement utile lorsque vous essayez de détecter des problèmes de performances dans un système en direct, car cela vous permet de tester des théories sur ce qui pourrait se passer rapidement et avec un impact minimal.

perf n'est pas seulement un profileur, il prend également en charge le traçage. Le profilage est basé sur l'échantillonnage de l'état du système lorsqu'il est déclenché par des compteurs de performances matériels ou logiciels ; il donne un échantillonnage statistique des points où le système passe le plus de temps. Au lieu de cela, le suivi prend des échantillons chaque fois qu'un événement de suivi particulier se produit, il est donc beaucoup plus utile pour les événements peu fréquents mais importants.

Lorsque vous travaillez avec PostgreSQL, l'une des fonctionnalités les plus intéressantes de perf est la capacité de tracer les processus de l'espace utilisateur . Vous voulez savoir à quelle fréquence votre PostgreSQL échange des segments WAL, à quelle fréquence il effectue des recherches de clés étrangères, etc. ? Pour un backend PostgreSQL ou pour l'ensemble du cluster ? perf peut vous aider.

Les points de trace de l'espace utilisateur et de l'espace noyau peuvent être mélangés et peuvent être utilisés en même temps que le profilage des compteurs de performances pour vous aider à obtenir une bonne image du système. perf peut capturer des traces de pile à partir du noyau et de l'espace utilisateur, et peut également effectuer des visualisations statistiques. Les points de trace de l'espace utilisateur sont créés avec des sondes dynamiques ; ceux de l'espace noyau peuvent être prédéfinis ou peuvent être des sondes dynamiques.

Alors, comment utilisez-vous certaines de ces fonctionnalités ?

Installer les outils

Tout d'abord, assurez-vous que vous utilisez une perf actuelle . Cet article a été écrit sur Fedora 19 avec perf 3.11.6 sur x86_64, et certaines fonctionnalités sont relativement nouvelles.

Si vous voulez des résultats de pile d'espace utilisateur, vous voudrez que le code que vous regardez soit construit avec -Og -ggdb -fno-omit-frame-pointer . Si vous utilisez un perf construit avec libunwind vous n'avez pas besoin de pointeurs de cadre ; voir ce post Stack Overflow et RH Bugzilla #1025603. Rien de tout cela n'est nécessaire si vous n'êtes intéressé que par les données côté noyau. Si vous utilisez des packages de distribution, vous devrez peut-être installer -debuginfo paquets aussi.

Tous les tests suivants ont été exécutés avec les packages PGDG PostgreSQL 9.2 de stock de http://yum.postgresql.org/ en utilisant un perf reconstruit avec libunwind assistance conformément aux instructions ci-dessus.

Points de trace et sondes du noyau

perf peut capturer des données à partir de points de trace prédéfinis du noyau, dont certains sont informatifs lorsque vous examinez des problèmes de fragmentation de la mémoire, d'E/S de disque, etc. Vous pouvez obtenir une liste de points de trace avec sudo perf list . Des listes de points de trace peuvent être spécifiées et les caractères génériques sont pris en charge. Par exemple, si nous voulons obtenir des statistiques d'écriture et de vidage de disque sur une instance PostgreSQL en cours d'exécution, nous pouvons exécuter :

sudo perf record -g dwarf -e block:block_rq_issue,syscalls:sys_enter_fsync -u postgres sleep 10

pour capturer les données. Au lieu de dormir, vous pouvez n'utiliser aucune commande et appuyer sur control-C lorsque vous avez terminé la capture, ou vous pouvez utiliser une autre commande comme psql -c pour déclencher la charge de travail que vous souhaitez mesurer.

-u postgres profile tous les processus exécutés en tant qu'utilisateur postgres . Vous pouvez à la place utiliser -a pour le profilage de l'ensemble du système sur tous les processeurs. Il est également possible de tracer un seul backend. Démarrer psql , lancez select pg_backend_pid() , lancez perf avec -p $the_pid , puis démarrez la charge de travail dans le même psql séance.

Lorsque vous travaillez avec PostgreSQL, le processus cible par défaut, qui est la commande exécutée sous le contrôle de perf , n'est généralement pas très utile car le backend fait la majeure partie du travail, pas psql . Il est toujours utile d'utiliser la sous-commande pour contrôler la charge de travail et le timing du test.

Une fois que vous avez capturé les données, vous pouvez utiliser le rapport de performances pour l'examiner. Il y a trop d'options à discuter ici - pour contrôler l'agrégation et la simplification des résultats, l'affichage de la trace de la pile, les cursus interactifs par rapport à la sortie du rapport texte, et plus encore.

Prenons cette session comme exemple, où il y a une session shell (terminal "T2") et une session postgres connectée à la base de données "regress" (terminal "T1") :

T1| regress=> sélectionnez pg_backend_pid();T1| pg_backend_pid T1| ----------------T1| 4495T1|(1 rangée)

T2| $ sudo perf record -g dwarf -e block:block_rq_*,syscalls:sys_enter_write,syscalls:sys_enter_fsync -p 4495

T1| regress=> créer une table x en sélectionnant un FROM generate_series(1,1000000) a;T1| régression=>

T2| $ ^CT2| [ enregistrement perf :réveillé 332 fois pour écrire des données ]T2| [ enregistrement de perf :Capture et écriture de 86,404 Mo de données de perf (~3775041 échantillons) ]T2|T2| $ sudo perf report -g

Vous pouvez utiliser le rapport de performances 's curses gui pour creuser dans la trace, ou vous pouvez utiliser le perf report --stdio option pour l'amener à diffuser des données sur stdout. Par exemple, si vous voulez des traces de pile, vous pouvez exécuter :

$ sudo perf report -g --stdio... blah blah ...# Échantillons :1 de l'événement 'syscalls:sys_enter_fsync'# Nombre d'événements (environ) :1## Overhead Command Shared Object Symbol# .. ...... ........ ............. .....................# 100,00 % postgres libc-2.17.so [.] __GI___libc_fsync | --- __GI___libc_fsync mdimmedsync heap_sync intorel_shutdown standard_ExecutorRun ExecCreateTableAs PortalRunUtility PortalRunMulti PortalRun PostgresMain ServerLoop PostmasterMain main __libc_start_main _start (nil)... bla bla...

montrant que pour l'événement syscalls:sys_enter_fsync il y avait un événement avec la pile ci-dessus, un fsync appelé via ExecCreateTableAs .

(Pour une raison, je n'ai pas encore été en mesure de déterminer le dernier fsync() ne semble pas être capturé par perf quand psql est exécuté directement sous le contrôle de perf . Ce n'est pas un problème avec stat de perf , uniquement enregistrement de performances . C'est pourquoi je saute à travers des cerceaux pour présélectionner le backend par pid ci-dessus.)

Sondes dynamiques de l'espace utilisateur

Parfois, vous êtes plus intéressé par quelque chose qui se passe dans PostgreSQL lui-même que par des événements dans le noyau qui sont déclenchés par PostgreSQL. Nouvelles versions de perf peut vous aider en insérant des points de trace dynamiques qui se déclenchent sur les appels dans les programmes de l'espace utilisateur.

Disons que vous êtes intéressé par l'activité WAL et que vous voulez voir quand XLogFlush , XLogFileInit ou XLogFileOpen sont appelés. Vous pouvez insérer des points de trace dynamiques pour ces appels avec perf :

sudo perf probe -x `which postgres` XLogFileInitsudo perf probe -x `which postgres` XLogFileOpensudo perf probe -x `which postgres` XLogFlush

Vous ne pouvez sonder que les symboles externes (non statiques, non masqués par les drapeaux -fvisibility) à moins que vous n'ayez construit avec -ggdb . perf se plaindra aucun symbole trouvé si vous essayez d'utiliser un symbole qui n'existe pas. Au moment de la rédaction perf ne prend pas en charge l'utilisation de debuginfo externe pour rechercher des symboles pour les sondes, bien qu'il puisse l'utiliser pour l'analyse de la pile. En général, s'il s'agit d'un extern dans src/include vous pouvez l'utiliser avec perf .

Chaque point de trace imprimera le nom du point de trace créé et vous pouvez utiliser perf probe -l pour tous les lister quand même :

$ sudo perf probe -l probe_postgres:XLogFileInit (sur 0x000000000009a360) probe_postgres:XLogFileOpen (sur 0x000000000009a860) probe_postgres:XLogFlush (sur 0x00000000000a0670)

Ces sondes sont maintenant utilisables en tant qu'événements perf. Jetons un coup d'œil à l'activité xlog pendant un exemple de charge de travail, en surveillant l'ensemble du cluster pendant que j'exécute une exécution pgbench :

sudo perf record -g nain -u postgres -e probe_postgres:XLogFileInit,probe_postgres:XLogFileOpen,probe_postgres:XLogFlush

Essayez vous-même avec perf report -g . Voici à quoi ressemblent les résultats. Vous pouvez utiliser des options comme -g fractal,0 pour contrôler les détails. Vous pourrez voir le pourcentage de hits d'un compteur donné provenant d'une branche de pile ou d'une autre, le pid et le processus, etc. Le --sort les options vous donnent plus de contrôle sur l'agrégation et le regroupement.

Mais attendez, il y a plus

Vous devriez également consulter les stats de performances et haut de performance commandes. Ils peuvent prendre les mêmes listes d'événements que perf record , bien que pour une raison étrange, leur prise en charge des filtres de processus soit différente.

Voici un exemple qui exécute une charge de travail factice et examine les points de trace du noyau d'E/S pendant l'exécution :

$ sudo perf stat -e block:block_rq_*,syscalls:sys_enter_write,syscalls:sys_enter_fsync -a -r 5 -- psql -q -U postgres craig -c "supprimer la table si elle existe x ; créer la table x en sélectionnant un FROM generate_series(1,1000000) a ;" ; Statistiques du compteur de performances pour 'psql -U postgres craig -c drop table if exists x; créer la table x en tant que select a FROM generate_series(1,1000000) a;' (5 exécutions) :0 block:block_rq_abort [100.00%] 0 block:block_rq_requeue [100.00%] 97 block:block_rq_complete ( +- 14.82% ) [100.00%] 96 block:block_rq_insert ( +- 14.97% ) [100.00%] 98 block:block_rq_issue ( +- 14.67% ) [100.00%] 0 block:block_rq_remap [100.00%]10,607 syscalls:sys_enter_write ( +- 0.17% ) [100.00%] 1 syscalls:sys_enter_fsync 0.908835058 secondes de temps écoulé ( +- 18.31% ) /pré>

Vous pouvez voir qu'il fait une moyenne d'environ 100 requêtes d'E/S de couche de bloc sur 10 000 écritures() et fait un seul fsync(). Une partie de cela est un bruit de fond du système puisque nous faisons tout le profilage du système (-a ), mais comme le système est assez inactif, ce n'est pas beaucoup, et la moyenne est calculée sur cinq exécutions.

De même, en utilisant les sondes dynamiques que nous avons ajoutées précédemment, gardez un œil sur l'activité de xlog lors d'une exécution de pgbench :

$ sudo perf stat -e probe_postgres:XLogFileInit,probe_postgres:XLogFileOpen,probe_postgres:XLogFlush -a -- /usr/pgsql-9.2/bin/pgbench -U postgres craig -c 2 -t 10000starting vacuum...end. type de transaction :TPC-B (sorte de)facteur de mise à l'échelle : 100mode de requête :simplenombre de clients :2nombre de threads :1nombre de transactions par client :10000nombre de transactions réellement traitées :20000/20000tps =715,854663 (y compris l'établissement des connexions)tps =716,092133 ( à l'exclusion de l'établissement des connexions) Statistiques du compteur de performances pour '/usr/pgsql-9.2/bin/pgbench -U postgres craig -c 2 -t 10000' :64 probe_postgres:XLogFileInit [100,00 %] 0 probe_postgres:XLogFileOpen [100,00 %] 55 440 probe_postgres :XLogFlush 27,987364469 secondes écoulées

Vous pouvez faire beaucoup plus, y compris capturer l'état des variables locales avec perf probe . J'écrirai quelques exemples utiles de celui-ci plus tard. En attendant, jouez, explorez et amusez-vous avec un nouvel outil de diagnostic.

Mise à jour : Michael Paquier a récemment écrit un article connexe sur le traçage de PostgreSQL avec systemtap qui pourrait intéresser les lecteurs de celui-ci. Vous devez recompiler Pg pour utiliser cette approche, mais la syntaxe est plus agréable et offre d'autres avantages.