Analyse des performances avec strace
Récemment, j’ai eu un client au téléphone qui se plaignait d’un script lent. Il s’agissait d’une importation, qui dure habituellement plusieurs heures.
Le code source ne vient pas de moi et le script accède à plusieurs bases de données sur différents serveurs.
Les outils habituels d’analyse de la performance n’ont pas pu être utilisés ici : Pour au moins une base de données, nous n’avons pas assez de droits, par exemple pour activer et surveiller le journal MySQL Slow Query.
Après un premier aperçu du code source, nous constatons que le script envoie de nombreuses requêtes et copie et traite de nombreux fichiers. Donc nous devons d’abord trouver ce qui est vraiment lent. Est-ce vraiment la base de données ? Ou à la fin du transfert de données ?
Aberrations
Le premier réflexe dans de tels cas est souvent de vérifier les requêtes SQL pour détecter les modèles inefficaces et de vérifier les bases de données pour détecter les index manquants.
Certaines des questions présentaient effectivement de telles caractéristiques – par exemple, la condition suivante est suspecte à un stade précoce :
WHERE `p`.`product_ean` LIKE '%123456789'
Comme on apprend relativement tôt à l’école, de telles requêtes ne peuvent pas être couvertes par un index et sont donc toujours associées à un scan de table – ce qui peut encore être possible pour une petite quantité de données, mais est garanti pour conduire à des problèmes à mesure que la quantité de données augmente.
Mais : Laquelle de ces requêtes dans le code est vraiment problématique ? Et : Comment les requêtes doivent-elles être corrigées ? La majuscule indique un EAN et nous pouvons supposer que les zéros non significatifs doivent être couverts ici. Mais les hypothèses peuvent mener à des erreurs d’appréciation, alors nous continuons à vérifier les faits.…
Buts fixés
Il est important que nous ne perdions pas de vue cet objectif. Lesquelles de ces requêtes inefficaces sont vraiment problématiques ? Et lequel d’entre eux pouvons-nous ignorer ? Et à quelle fréquence toutes ces requêtes sont-elles exécutées ?
Je suis fan de l’outil stracedepuis longtemps. strace” enregistre tous les appels système d’un programme. Vous pouvez donc voir quels sont les effets réels d’un programme sur son environnement. Comme notre script ralentit probablement principalement à cause des interactions avec les systèmes environnants, je pense que nous avons le bon outil ici.
Debugging
Donc je lance Strace et je l’ajoute avec le paramètre `-p $PID’ au processus déjà lancé.
# strace -p 933950
Process 933950 attached
write(1, "Produkt wurde erfolgreich aktual"..., 133) = 133
sendto(5, "\334\4\0\0\3\n\t\t\tSELECT\n\t\t\t\tentryID AS I"..., 1248, MSG_DONTWAIT, NULL, 0) = 1248
poll([{fd=5, events=POLLIN|POLLERR|POLLHUP}], 1, 1471228928) = 1 ([{fd=5, revents=POLLIN}])
recvfrom(5, "\1\0\0\1\30+\0\0\2\3def\6mmdb15\1t\5Entry\2ID\7"..., 1139, MSG_DONTWAIT, NULL, NULL) = 1139
poll([{fd=5, events=POLLIN|POLLERR|POLLHUP}], 1, 1471228928) = 1 ([{fd=5, revents=POLLIN}])
recvfrom(5, "\31\3def\6mmdb15\1t\5Entry\10statusID\10st"..., 1519, MSG_DONTWAIT, NULL, NULL) = 69
sendto(5, "\304\0\0\0\3\n\t\t\t\tSELECT\n\t\t\t\t\tEAN,\n\t\t\t\t\t"..., 200, MSG_DONTWAIT, NULL, 0) = 200
poll([{fd=5, events=POLLIN|POLLERR|POLLHUP}], 1, 1471228928) = 1 ([{fd=5, revents=POLLIN}])
recvfrom(5, "\1\0\0\1\10,\0\0\2\3def\6mmdb15\5Track\5Track"..., 1450, MSG_DONTWAIT, NULL, NULL) = 443
Ok, je vois beaucoup d'interactions ici, mais j'ai l'impression que la sortie s'arrête pendant une fraction de seconde de temps en temps. Que se passe-t-il exactement ? Je soupçonne déjà que le script attend la réponse d'une base de données. Peut-on vérifier où le script est accroché exactement ?
Il s'avère - oui, vous pouvez : `strace' connaît une option `-c', qui ne génère pas de sortie "live", mais à la fin (après avoir interrompu la strace, ou le processus cible est terminé) il retourne une statistique. Ça a l'air bien. Essayons :
```bash
# strace -p 933950 -c
Process 933950 attached
^CProcess 933950 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
46.43 0.000970 10 99 poll
45.14 0.000943 236 4 stat
3.49 0.000073 5 16 lstat
3.45 0.000072 1 71 sendto
0.91 0.000019 0 100 recvfrom
0.19 0.000004 0 48 write
0.19 0.000004 0 16 open
0.05 0.000001 0 22 lseek
0.05 0.000001 0 6 mmap
Et ici nous voyons déjà le premier suspect : poll' est appelé très souvent et consomme donc la plupart du temps ! stat cependant nous pouvons probablement négliger pour le moment, car il est appelé seulement 4 fois.poll’ est utilisé pour attendre les réponses du réseau. Un programme a besoin de cet appel système pour s’endormir jusqu’à ce que les données soient à nouveau transmises par un pair distant. Mais quelles données ? Et comment pouvons-nous utiliser cette information pour trouver des solutions possibles à notre problème actuel ?
Si nous regardons à nouveau la sortie d’en haut, nous voyons un modèle d’appels système : un sendto' est toujours fait, suivi parpoll’ et finalement `recvfrom’. Comme leur nom l’indique, ces appels système sont responsables de l’envoi et de la réception des données via le réseau.
Nous pouvons donc maintenant voir combien de temps cela prend exactement entre une paire sendto' et une pairerecvfrom’. Peut-être que ça nous donnera une idée ! Mais quel est le moyen le plus simple ?
Manpage to the rescue!
Après avoir lu la page de manuel de `strace’ je trouve une option qui me semble très utile :
-r Print a relative timestamp upon entry to each system call.
This records the time difference between the beginning of
successive system calls.
Avec cette option, je peux voir combien de temps s’est écoulé depuis le dernier appel système. Quelques réflexions, puis l’éclair de génie : Que se passe-t-il si je n’affiche que les deux appels systèmesendto' etrecvfrom’ avec `strace’ et filtre le reste ? Voyons voir :
strace -p 933950 -r -e recvfrom,sendto
Process 933950 attached
0.000169 sendto(4, "\v\1\0\0\3\n\t\t\tSELECT\n\t\t\t\t`image_name`"..., 271, MSG_DONTWAIT, NULL, 0) = 271
1.036864 recvfrom(4, "\1\0\0\1\1^\0\0\2\3def\21sometable\1"..., 131, MSG_DONTWAIT, NULL, NULL) = 131
0.000088 recvfrom(4, "0.jpg\5\0\0\5\376\0\0\"\0", 173, MSG_DONTWAIT, NULL, NULL) = 14
Parfait ! Parfait ! Parfait ! Et déjà attrapé un suspect ! Là nous avons une requête (vous voyez un SELECT') et quelques noms de tables dans la sortie (lignerecvfrom’). Intéressant. Mais ce n’était peut-être qu’une fugue statistique. Parce que les autres appels ont besoin de beaucoup moins et je ne vois pas toute la requête.
Vous êtes encerclés !
Nous savons donc ce qu’il faut chercher. Il ne reste plus qu’à remettre les pendules à l’heure et à voir ce qui se passe. Voilà mon plan :
Nous écrivons strace' dans un fichier (option-o’), trions les appels par temps et devrions trouver statistiquement les requêtes les plus lentes.
Et pendant que nous y sommes, nous aimerions voir quelles questions sont à blâmer. La sortie ci-dessus nous montre que strace' raccourcit fortement les arguments des longues chaînes de caractères. Dans la page de manuel, nous trouvons le paramètre-s’, avec lequel nous pouvons spécifier la force du raccourcissement. Nous voulons toutes les données possibles ; je spécifie donc un paramètre extrêmement long de 10000 caractères. Alors :
# strace -p 933950 -r -e sendto,recvfrom -s 10000 -o import_db_stats.txt
Process 933950 attached
Nous laissons la trace s’exécuter un peu et puis nous abandonnons avec `Ctrl-C’. Ensuite, nous trions l’enregistrement numériquement et regardons les dernières lignes :
# sort -n import_db_stats.txt | tail -n5
0.749176 recvfrom(4, "\1\0\0\1\1^\0\0\2\3def\21sometable\1i\"product_images\nimage_name\nimage_name\f!\0\375\2\0\0\375\1P\0\0\0\5\0\0\3\376\0\0\"\0\24\0\0\4\0231234567890_1.jpg\5\0\0\5\376\0\0\"\0", 159, MSG_DONTWAIT, NULL, NULL) = 145
0.769669 recvfrom(4, "\1\0\0\1\1^\0\0\2\3def\21sometable\1i\"product_images\nimage_name\nimage_name\f!\0\375\2\0\0\375\1P\0\0\0\5\0\0\3\376\0\0\"\0\24\0\0\4\0231234567890_0.jpg\5\0\0\5\376\0\0\"\0", 172, MSG_DONTWAIT, NULL, NULL) = 145
0.803661 recvfrom(4, "\1\0\0\1\1^\0\0\2\3def\21sometable\1i\"product_images\n", 69, MSG_DONTWAIT, NULL, NULL) = 69
0.814297 recvfrom(4, "\1\0\0\1\1^\0\0\2\3def\21me", 16, MSG_DONTWAIT, NULL, NULL) = 16
0.947148 recvfrom(4, "\1\0\0\1\1^\0\0\2\3def\21sometable\1i\"product_images\nimage_name\nimage_name\f!\0\375\2\0\0\375\1P\0\0", 102, MSG_DONTWAIT, NULL, NULL) = 102
Oh, merveilleux ! Nous avons donc les cinq appels les plus lents (respectivement ceux avec le temps d’attente le plus long avant), tous sont `recvfrom’ et aussi de la même base de données (le premier paramètre correspond au gestionnaire de fichier respectivement à la socket). Bonus : Quatre de ces appels contiennent des données du même tableau ! Jackpot !
Attendez – mais comment puis-je maintenant voir les requêtes, qui sont lentes ? Les recvfrom' concernent uniquement la lecture des résultats. Nous nous souvenons - la requête est généralement envoyée directement avant d'utilisersendto’. Il suffit donc de rechercher les lignes correspondantes dans la sortie (non triée !) et de trouver le prédécesseur.
Je pense que les horodatages relatifs sur le court laps de temps sont suffisamment clairs pour servir de paramètres de recherche. C’est pourquoi nous n’obtenons ces résultats qu’à partir des résultats ci-dessus :
# sort -n import_db_stats.txt | tail -n5 | awk '{print $1}'
0.749176
0.769669
0.803661
0.814297
0.947148
Parfait ! Et avec grep' nous pouvons maintenant trouver les lignes qui l'ont précédé. Le paramètre-B` nous aide à le faire. Parce que nous ne voulons pas les résultats, nous les filtrons tout de suite :
# sort -n import_db_stats.txt | tail -n5 | awk '{print $1}' > slowest_times.txt
> for time in $(cat slowest_times.txt); do
> grep -B1 $time import_db_stats.txt | grep -v $time
> done
0.000091 sendto(4, "\v\1\0\0\3\n\t\t\tSELECT\n\t\t\t\t`image_name`\n\t\t\tFROM\n\t\t\t\t`product_images` AS `i`\n\t\t\tJOIN\n\t\t\t\t`products` AS `p`\n\t\t\t\t\tUSING (`product_id`)\n\t\t\tWHERE\n\t\t\t\t`image_name` LIKE '12345678896_1.jpg'\n\t\t\t\tAND\n\t\t\t\t`p`.`product_ean` LIKE '%12345678896'\n\t\t", 271, MSG_DONTWAIT, NULL, 0) = 271
0.000222 sendto(4, "\v\1\0\0\3\n\t\t\tSELECT\n\t\t\t\t`image_name`\n\t\t\tFROM\n\t\t\t\t`product_images` AS `i`\n\t\t\tJOIN\n\t\t\t\t`products` AS `p`\n\t\t\t\t\tUSING (`product_id`)\n\t\t\tWHERE\n\t\t\t\t`image_name` LIKE '1234567890134_0.jpg'\n\t\t\t\tAND\n\t\t\t\t`p`.`product_ean` LIKE '%1234567890134'\n\t\t", 271, MSG_DONTWAIT, NULL, 0) = 271
0.000196 sendto(4, "\v\1\0\0\3\n\t\t\tSELECT\n\t\t\t\t`image_name`\n\t\t\tFROM\n\t\t\t\t`product_images` AS `i`\n\t\t\tJOIN\n\t\t\t\t`products` AS `p`\n\t\t\t\t\tUSING (`product_id`)\n\t\t\tWHERE\n\t\t\t\t`image_name` LIKE '1234567890189_0.jpg'\n\t\t\t\tAND\n\t\t\t\t`p`.`product_ean` LIKE '%1234567890189'\n\t\t", 271, MSG_DONTWAIT, NULL, 0) = 271
0.000089 sendto(4, "\v\1\0\0\3\n\t\t\tSELECT\n\t\t\t\t`image_name`\n\t\t\tFROM\n\t\t\t\t`product_images` AS `i`\n\t\t\tJOIN\n\t\t\t\t`products` AS `p`\n\t\t\t\t\tUSING (`product_id`)\n\t\t\tWHERE\n\t\t\t\t`image_name` LIKE '1234567890134_1.jpg'\n\t\t\t\tAND\n\t\t\t\t`p`.`product_ean` LIKE '%1234567890134'\n\t\t", 271, MSG_DONTWAIT, NULL, 0) = 271
0.000167 sendto(4, "\v\1\0\0\3\n\t\t\tSELECT\n\t\t\t\t`image_name`\n\t\t\tFROM\n\t\t\t\t`product_images` AS `i`\n\t\t\tJOIN\n\t\t\t\t`products` AS `p`\n\t\t\t\t\tUSING (`product_id`)\n\t\t\tWHERE\n\t\t\t\t`image_name` LIKE '1234567890103_0.jpg'\n\t\t\t\tAND\n\t\t\t\t`p`.`product_ean` LIKE '%1234567890103'\n\t\t", 271, MSG_DONTWAIT, NULL, 0) = 271
Merveilleux. Comme déjà suspecté au tout début, c’est l’une des requêtes qui fait une recherche LIKE avec un joker de démarrage.
Il ne nous reste plus qu’à rechercher la requête correspondante dans le code et à réfléchir à la manière de l’optimiser. Mais je n’ai plus besoin d’expliquer cela ; aujourd’hui, il s’agissait de chercher un problème d’une autre manière.
résultat net
Nous apprenons donc que Linux fournit avec `strace’ un outil merveilleux pour trouver non seulement les problèmes généraux, mais aussi pour l’analyse des performances. Ce qui est bien, c’est que vous pouvez déjà apprendre beaucoup de choses sur un programme ici, surtout si vous n’avez pas accès au code source.
J’ai utilisé `strace’ principalement pour déboguer des programmes suspendus ou analyser ce que fait exactement un programme.
Les paramètres les plus importants de la ” strace ” sont à nouveau résumés :
-oécrit la sortie dans un fichier-rmontre le temps relatif depuis le dernier système enregistré ( !)
coup de fil-speut être utilisé pour définir le raccourci du paramètre string-ccrée un profil d’appel pour les appels appelés
strace peut faire beaucoup plus, il vaut donc la peine de simplement télécharger la page de manuel survoler.