Sommaire
-
Appeler
stracesur un processus existant - Lancer le processus avec
stracepour un historique complet - Filtrer les appels systèmes avec
-e - Le mystère reste malgré tout entier
- Épiphanie – regarder le bon fautif
Journal un peu rapide orienté debug de perf et découverte de strace.
J’héberge une instance privée d'Invidious. 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.
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="@K\1\0\0\1\0\0\0\0\0\0\1i\5ytimg\3com\0\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="\273N\1\0\0\1\0\0\0\0\0\0\1i\5ytimg\3com\0\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<anon_inode:[eventpoll]>, [], 32, 3637, NULL, 8) = 0
epoll_pwait(6<anon_inode:[eventpoll]>, [], 32, 5, NULL, 8) = 0
epoll_pwait(6<anon_inode:[eventpoll]>,
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… :-)
# it's always DNS
Posté par Krunch (site web personnel) . Évalué à 8.
Ah, un problème de DNS.
Bon c'est dommage que tu n'ai pas réussi à le diagnostiquer complètement. Si tu veux aller au fond du problème, je suggère les actions suivantes :
- mettre en place une version avec et sans le problème
- stracer les deux séparément
- tcpdumper les deux séparément (en même temps que le strace)
- comparer pour trouver ce qui est lent
Pour strace, tu voudra aussi utiliser -f -ttt -T. Et, oui, on se retrouve vite à écrire de quoi parser la sortie. Alternativement, tu peux te mettre à un truc genre SystemTap ou perf(?) mais j'ai un peu perdu le fil de ce qui se fait dans ce domaine de nos jours.
Pour tcpdump, je recommande d'analyser le résultat avec wireshark.
pertinent adj. Approprié : qui se rapporte exactement à ce dont il est question.
[^] # Re: it's always DNS
Posté par raphj . Évalué à 4.
Le DNS était une de mes premières hypothèses, mais non, ce n'était pas ça.
C'était plus des directives
proxy_passtoutes merdiques, ou un truc du genre. Si je voulais vraiment connaître la raison du problème, il faudrait que je joue avec la vieille configuration nginx merdique, mais en réalité, je vais vouloir passer du temps sur d'autres trucs donc je ne suis pas sûr que je vais me replonger là dedans.Je sais, je sais, ça laisse tout le monde sur sa faim :-P
Merci pour les suggestions d'options de strace, je jetterai un œil.
[^] # Re: it's always DNS
Posté par Krunch (site web personnel) . Évalué à 2.
Je connais ni nginx ni proxy_pass mais en lisant https://nginx.org/en/docs/http/ngx_http_proxy_module.html#proxy_pass et en particulier ceci :
Il me semble vraisemblable que tu avais une directive qui pointait vers une entrée DNS moisie qui faisait en sorte qu'il y avait une connexion HTTP (je dis plus TCP parce que de nos jours c'est de moins en moins le cas) vers un truc qui n'existe pas et que cette connexion mettait un certains temps à timeouter avant de passer à l'entrée suivant qui marche.
Et tu aurais pu diagnostiquer cela assez vite en tcpdumpant le traffic DNS (en admettant que tu n'utilises pas DNS over HTTPS/SSL) mais strace ne t'aurait pas beaucoup aidé.
pertinent adj. Approprié : qui se rapporte exactement à ce dont il est question.
[^] # Re: it's always DNS
Posté par raphj . Évalué à 2. Dernière modification le 03 septembre 2024 à 22:49.
Vraisemblable. Tu vas finir par réussir à me pousser à la faire, cette autopsie ! C'est vrai que ce serait satisfaisant de savoir. Maintenant qu'il n'y a plus la frustration de "pourquoi ça ne marche pas, merde, je veux dépenser mon temps autrement", ça sera plus serein. De toute façon j'ai une sauvegarde du serveur dans l'état cassé. Faudrait surveiller le trafic DNS, en effet, et éventuellement prêter attention aux échanges entre Invidious et nginx. La suite peut-être dans un prochain journal, peut-être dans quelques mois, années. Ou, qui sait, dans la semaine en réponse à ce commentaire.
# utilisation de sudo
Posté par moi1392 . Évalué à 4.
Pour contourner le problème d'interdition de ptrace, tu utilises sudo. C'est peut-être la bonne solution dans ton cas, mais il y a aussi la possibilité (avec tout les risques que cela comporte) d'autoriser les utilisateurs à ptrace leurs processus en modifiant le bon paramètre du kernel :
En tant que développeur qui débogue régulièrement des programmes sur ma machine, c'est un des premiers réglage que je fais (que j'oublie de faire, plus exactement…) lors d'une nouvelle installation.
[^] # Re: utilisation de sudo
Posté par raphj . Évalué à 2.
Je me doutais que ce genre de truc existait, merci pour la mention. Il y a peut-être aussi des solutions à base de groupe unix ?
En tout cas ça me va bien que ça ne soit pas actif sur mon serveur, c'est bien de devoir être root. Sur ma machine de dev, j'y penserai la prochaine fois, c'est pratique que le débogueur tourne en tant que l'utilisateur normal :-)
À noter que lorsqu'on demande à strace de lancer le processus, aucun droit particulier n'est nécessaire (comme gdb, finalement, vu que ça passe aussi par ptrace). J'utilise sudo pour lancer invidious en tant que l'utilisateur qui lui est dédié (tu le sais déjà, c'est plus le lecteur ou la lectrice à qui ça aurait échappé).
[^] # Re: utilisation de sudo
Posté par moi1392 . Évalué à 3.
C'est l'idée effectivement, car autrement si un malware arrive à exécuter du code en tant que ton utilisateur sur ta machine, il peux ptrace les autres processus et lire leur mémoire, ça veut dire potentiellement lire la mémoire de firefox ou ssh et y trouver des mots de passe en clair.
C'est pour cela que par défaut, un processus ne peux ptrace que ses processus enfant, c'est à dire ceux qui ont été lancés par lui ou par un de ses enfants.
Car un process peut toujours ptrace un de ses enfants. Mais il est possible d'interdire cela aussi (voir le lien plus bas)
j'ai un peu cherché et j'ai trouvé quelque chose qui pourrait être intéressant, un processus peut demander à être éxonéré de cette restriction grace à un appel système. Comme je m'attache à des processus de binaires que je développe, je peux facilement ajouter cet appel système dans mon code pour être tranquille et ne pas avoir à réduire la sécurité de toute mon installation.
https://www.man7.org/linux/man-pages/man2/PR_SET_PTRACER.2const.html
[^] # Re: utilisation de sudo
Posté par freem . Évalué à 3.
Pour les développeurs et autres qui poussent un peu, il y a d'autres réglages noyau qui peuvent être pertinents:
kernel.dmesg_restrict = 0parce que c'est quand même sympa de pouvoir dmesg pour avoir 2-3 infos sur un crash;vm.overcommit_memory = ?qui permets d'éviter de freeze son système à cause d'un bug bien gras de mémoire (oui ça m'est arrivé)echo 3 > /proc/sys/kernel/perf_event_paranoidpermets d'utiliserperfl'outil de monitoring du noyal. Très pratique, d'ailleurs je me suis fait un "script" qui l'active et rappelle comment s'en servir vu que j'oublie tout le temps:Perso, si tu as des problèmes de perf à analyser, je recourrais plutôt à
perfqu'astracecela dit, c'est un peu plus fait pour, même si je ne sais pas s'il te serait utile pour ce cas précis que tu as eu.# Invidious
Posté par Shyne . Évalué à 1.
Merci pour la découverte de ce frontend youtube, je ne connaissais pas.
# trace-cmd
Posté par snoopy . Évalué à 0.
A noter qu'il existe d'autre front-end à ftrace, notamment https://trace-cmd.org/, que je trouve assez pratique dans mon contexte.
Cet outil génère d'abord un fichier binaire, plus rapide à écrire sur disque et donc avec moins de perturbation du processus sous tests.
Ensuite on génère un fichier texte pour nous autres humains (si tant est que les syscalls soient des trucs human-readable). On peut générer ce rapport autant de fois que l'on veux, en modifiant les filtres à notre guise.
Enfin, ftrace nous autorise à instrumenter nous-même nos programmes en écrivant dans /proc. Par exemple:
fprintf(/sys/kernel/debug/tracing/trace_marker, "I am here!");
echo "Hello" > /sys/kernel/debug/tracing/trace_marker
Ces traces apparaîtront dans le log de ftrace.
(à ma connaissance, le processus qui écrit doit forcément être root)
Suivre le flux des commentaires
Note : les commentaires appartiennent à celles et ceux qui les ont postés. Nous n’en sommes pas responsables.