URL: https://linuxfr.org/users/raphj/journaux/debugger-un-probleme-de-performance-avec-strace Title: Débugger un problème de performance avec strace Authors: raphj Date: 2024年09月01日T18:50:46+02:00 License: CC By-SA Tags: strace, performance, debugging et nginx Score: 34 Journal un peu rapide orienté debug de perf et découverte de `strace`. J’héberge une instance privée d'[Invidious](https://invidious.io/). C’est un frontal alternatif pour Youtube qui permet notamment de suivre des chaînes sans avoir de compte Google, et d’accéder à Youtube avec du code libre. C’est pas mal, en attendant que tout le monde se mette à [PeerTube](joinpeertube.org). Depuis des mois, il y avait une latence aléatoire au chargement des pages, des vidéos, de tout. Parfois tout s’affichait instantanément, et parfois, la galère, les choses mettaient plusieurs dizaines de secondes à charger. Frustrant. À force, cette perte de temps s’additionne. Hier, et en fait à plusieurs reprises, je me suis dit que j’allais tracer les appels systèmes pour voir s’il y en a qui bloquent, et sur quoi. Par exemple : - un échange avec le grand méchant Youtube qui aurait détecté mon utilisation de PeerTube et qui introduirait des lags pour faire chier - une requête PostgreSQL lente - un problème avec Redic On peut faire ça avec strace. J’ai fait quelques découvertes sur ses capacités que je vais résumer ici. # Appeler `strace` sur un processus existant C’est simple, il suffit d’appeler strace avec le PID du processus à tracer, comme ça : ``` sudo strace -p $(pidof invidious) ``` (l’utilisateur unix doit pouvoir utiliser ptrace pour avoir le droit d’inspecter des processus comme ça, je passe donc par root) Ça ressemble à ça : ``` getpid() = 2096012 openat(AT_FDCWD, "/usr/lib/ssl/cert.pem", O_RDONLY) = 19 newfstatat(19, "", {st_mode=S_IFREG|0644, st_size=213777, ...}, AT_EMPTY_PATH) = 0 read(19, "-----BEGIN CERTIFICATE-----\n..."..., 4096) = 4096 read(19, "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"..., 4096) = 4096 ... read(19, "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"..., 4096) = 785 read(19, "", 4096) = 0 close(19) = 0 newfstatat(AT_FDCWD, "/etc/nsswitch.conf", {st_mode=S_IFREG|0644, st_size=516, ...}, 0) = 0 newfstatat(AT_FDCWD, "/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=624, ...}, 0) = 0 openat(AT_FDCWD, "/etc/hosts", O_RDONLY|O_CLOEXEC) = 19 newfstatat(19, "", {st_mode=S_IFREG|0644, st_size=534, ...}, AT_EMPTY_PATH) = 0 lseek(19, 0, SEEK_SET) = 0 read(19, "127.0.0.1 localhost\n\n127.0.1.1"..., 4096) = 534 read(19, "", 4096) = 0 close(19) = 0 socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 19 setsockopt(19, SOL_IP, IP_RECVERR, [1], 4) = 0 connect(19, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.1.1")}, 16) = 0 ppoll([{fd=19, events=POLLOUT}], 1, {tv_sec=0, tv_nsec=0}, NULL, 0) = 1 ([{fd=19, revents=POLLOUT}], left {tv_sec=0, tv_nsec=0}) sendmmsg(19, [{msg_hdr={msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="@K1円0円0円1円0円0円0円0円0円0円1円i5円ytimg3円com0円0円1円0円1円", iov_len=29}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, msg_len=29}, {msg_hdr={msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="273円N1円0円0円1円0円0円0円0円0円0円1円i5円ytimg3円com0円0円34円0円1円", iov_len=29}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, msg_len=29}], 2, MSG_NOSIGNAL) = 2 ... epoll_pwait(6, ``` J’ai un peu raccourci et censuré la sortie, mais le principe c’est qu’on voit les appels systèmes avec leur nom, les paramètres, la valeur de retour, c’est cool. Sur la dernière ligne, on voit que le processus attend quelque chose sur le descripteur de fichier numéro 6 ; `epoll_pwait` n’a pas encore retourné, donc la ligne n’est pas finie. ## `--decode-fds` pour avoir les noms de fichiers Bon, 6, ce n’est pas très parlant. Premier réflexe : on pourrait écrire un outil qui analyse la sortie de strace et qui surveille qu’est-ce qu’on fait sur chaque descripteur, et des choses comme ça. Mais première découverte : strace permet de décoder ces numéros et d’afficher des informations utiles comme le nom de fichier en question. ``` sudo strace --decode-fds -p $(pidof invidious) strace: Process 2096012 attached epoll_pwait(6, [], 32, 3637, NULL, 8) = 0 epoll_pwait(6, [], 32, 5, NULL, 8) = 0 epoll_pwait(6, ``` Bon, là, ça n’aide pas trop, mais quand on a affaire à des fichiers, ça rend immédiatement la lecture plus claire. # Lancer le processus avec `strace` pour un historique complet Mais on peut vouloir suivre depuis le début pour voir quel numéro correspond à quoi, et avoir l’historique complet. ``` $ sudo systemctl invidious stop $ cd /home/invidious/invidious $ sudo -u invidious strace ./invidious ``` # Filtrer les appels systèmes avec `-e` Mais ça spamme à donf. Il se passe une quantité de bazar monstrueuse au démarrage d’un processus comme invidious. Alors, seconde découverte, `strace` est en fait capable de filtrer les appels systèmes qui nous intéressent : ``` sudo -u invidious strace --decode-fds -e desc,network ./invidious ``` Ici, je ne garde que les opérations sur les fichiers, et les opérations réseaux. En vrai, ça spamme encore beaucoup trop, mais je voulais montrer qu’on pouvait en mettre plusieurs. Ici, seules les opérations réseaux m’intéressent. On se référera au manuel pour avoir la liste des groupes d’appels systèmes sur lesquels on peut filtrer. Petite astuce additionnelle : quand on utilise `strace`, ça peut être très pratique d’activer l’historique illimité de son émulateur de terminal. # Le mystère reste malgré tout entier Malgré ces découvertes, je ne parviens pas à trouver la raison des latences. Rien de lisible dans la sortie de strace. Je suis sur le point d’abandonner et de me dire que je ne couperai pas à l’exploration de cette idée d’outil qui parse `strace`. On trouve des choses, mais un peu basiques. # Épiphanie – regarder le bon fautif À ce moment, une illumination me vient, il me prend l’idée d’aller voir la configuration nginx, qui tourne devant Invidious. Et en effet, elle est toute pourrie. Je retire du merdier laissé par une expérimentation, et tout se met à fonctionner impeccablement bien. Évidemment, c’est très peu satisfaisant de l’avoir découvert comme ça et pas par du debug, mais le problème ne venait pas d’Invidious. Je pouvais tracer tout ce que je pouvais, rien n’allait sortir. Au mieux, peut-être que j’aurais peut-être pu remarquer des paquets qui tardent à venir depuis nginx, mais je n’ai pas été assez fin pour le remarquer. Quand on a des hypothèses en tête, on ne voit pas forcément l’anguille sous la roche. Mais donc la leçon à retenir, c’est : pour étudier un problème de perf, il faut déjà instrumenter le bon processus. Je ne me serais pas douté qu’un problème vienne d’nginx, ça marche très bien et je n’ai jamais eu de problème. Mais mal configuré, il peut faire n’importe quoi. Mais bon, j’ai appris à mieux utiliser `strace`... :-)

AltStyle によって変換されたページ (->オリジナル) /