Linux dispose d'un grand nombre d'outils et d'applications de débogage du noyau. La plupart d'entre eux affectent négativement les performances des applications et ne peuvent pas être utilisés en production.
Il y a quelques années,
un autre outil a été
développé - eBPF. Il permet de tracer le noyau et les applications utilisateur avec une faible surcharge et sans avoir besoin de reconstruire des programmes et de charger des modules tiers dans le noyau.
Il existe déjà de nombreux utilitaires d'application qui utilisent eBPF, et dans cet article, nous verrons comment écrire notre propre utilitaire de profilage basé sur la bibliothèque
PythonBCC . L'article est basé sur des événements réels. Nous passerons de l'apparition du problème à sa correction pour montrer comment les utilitaires existants peuvent être utilisés dans des situations spécifiques.
Ceph est lent
Un nouvel hôte a été ajouté au cluster Ceph. Après avoir migré certaines des données vers celui-ci, nous avons remarqué que la vitesse de traitement des demandes d'écriture est beaucoup plus faible que sur d'autres serveurs.
Contrairement à d'autres plateformes, bcache et le nouveau noyau linux 4.15 ont été utilisés sur cet hôte. Un hôte de cette configuration a été utilisé ici pour la première fois. Et à cette époque, il était clair que, théoriquement, tout pouvait être à l'origine du problème.
EnquĂŞte sur l'hĂ´te
Pour commencer, voyons ce qui se passe à l'intérieur du processus ceph-osd. Pour ce faire, nous utilisons
perf et
flamescope (plus d'informations Ă ce sujet peuvent ĂŞtre lues
ici ):
L'image nous indique que la fonction
fdatasync () a passé beaucoup de temps à envoyer une requête à la fonction
generic_make_request () . Cela signifie que la cause des problèmes se situe probablement quelque part en dehors du démon osd lui-même. Il peut s'agir d'un noyau ou de disques. La sortie iostat a montré une latence élevée dans le traitement des demandes avec des disques bcache.
Lors de la vérification de l'hôte, nous avons constaté que le démon systemd-udevd consomme une grande quantité de temps CPU - environ 20% sur plusieurs cœurs. C'est un comportement étrange, vous devez donc en découvrir la cause. Puisque Systemd-udevd fonctionne avec les uevents, nous avons décidé de les regarder à travers le
moniteur udevadm . Il s'avère qu'un grand nombre d'événements de modification ont été générés pour chaque périphérique de bloc du système. Ceci est assez inhabituel, vous devrez donc voir ce qui génère tous ces événements.
Utilisation de la boîte à outils BCC
Comme nous l'avons déjà découvert, le noyau (et le démon ceph dans l'appel système) passe beaucoup de temps dans
generic_make_request () . Essayons de mesurer la vitesse de cette fonction.
BCC a déjà une grande utilité -
funclatency . Nous allons tracer le démon par son PID avec un intervalle entre les sorties d'information de 1 seconde et afficher le résultat en millisecondes.
Habituellement, cette fonction est rapide. Tout ce qu'elle fait, c'est envoyer la demande à la file d'attente des pilotes de périphérique.
Bcache est un périphérique complexe qui se compose en fait de trois disques:
- périphérique de sauvegarde (disque mis en cache), dans ce cas, il s'agit d'un disque dur lent;
- périphérique de mise en cache (disque de mise en cache), il s'agit ici d'une section du périphérique NVMe;
- périphérique virtuel bcache avec lequel l'application fonctionne.
Nous savons que la transmission des demandes est lente, mais pour lequel de ces appareils? Nous y reviendrons un peu plus tard.
Nous savons maintenant que les événements provoquent probablement des problèmes. Trouver ce qui cause exactement leur génération n'est pas si simple. Supposons que ce soit une sorte de logiciel qui s'exécute périodiquement. Voyons quel
type de logiciel est lancé sur le système à l'aide du script
execsnoop du mĂŞme
ensemble d'utilitaires BCC . Exécutez-le et dirigez la sortie vers un fichier.
Par exemple, comme ceci:
/usr/share/bcc/tools/execsnoop | tee ./execdump
Nous ne donnerons pas la sortie complète d'execsnoop ici, mais une ligne d'intérêt pour nous ressemblait à ceci:
sh 1764905 5802 0 sudo arcconf getconfig 1 AD | grep Temperature | awk -F '[:/]' '{print $2}' | sed 's/^ \([0-9]*\) C.*/\1/'
La troisième colonne est le PPID (PID parent) du processus. Le processus avec le PID 5802 s'est avéré être l'un des fils de notre système de surveillance. Lors de la vérification de la configuration du système de surveillance, des paramètres erronés ont été trouvés. La température de l'adaptateur HBA a été prise une fois toutes les 30 secondes, ce qui est beaucoup plus souvent que nécessaire. Après avoir modifié l'intervalle de vérification en un intervalle plus long, nous avons constaté que le retard dans le traitement des demandes sur cet hôte a cessé de se démarquer du reste des hôtes.
Mais on ne sait toujours pas pourquoi le périphérique bcache était si lent. Nous avons préparé une plate-forme de test avec une configuration identique et essayé de reproduire le problème en exécutant fio sur bcache, en démarrant périodiquement le déclencheur udevadm pour générer des événements.
Écriture d'outils basés sur BCC
Essayons d'Ă©crire un utilitaire simple pour tracer et afficher les appels les plus lents Ă
generic_make_request () . Nous sommes également intéressés par le nom du lecteur pour lequel cette fonction a été appelée.
Le plan est simple:
- Enregistrez kprobe dans generic_make_request () :
- Nous enregistrons le nom du disque accessible via l'argument de fonction;
- Enregistrez l'horodatage.
- Enregistrez kretprobe pour revenir de generic_make_request () :
- Obtenez l'horodatage actuel;
- Nous recherchons l'horodatage enregistré et le comparons avec l'actuel;
- Si le résultat est supérieur à celui spécifié, alors nous trouvons le nom du disque enregistré et l'afficher sur le terminal.
Les kprobes et les
kretprobes utilisent un mécanisme de point d'arrêt pour changer le code de fonction à la volée. Vous pouvez lire la
documentation et un
bon article sur ce sujet. Si vous regardez le code de divers utilitaires dans
BCC , vous remarquerez qu'ils ont une structure identique. Donc, dans cet article, nous allons omettre l'analyse des arguments de script et passer au programme BPF lui-mĂŞme.
Le texte eBPF à l'intérieur du script python ressemble à ceci:
bpf_text = “””
Pour échanger des données entre fonctions, les programmes eBPF utilisent
des tables de hachage . Nous aussi. Comme clé, nous utiliserons le PID du processus, et comme valeur nous définirons la structure:
struct data_t { u64 pid; u64 ts; char comm[TASK_COMM_LEN]; u64 lat; char disk[DISK_NAME_LEN]; }; BPF_HASH(p, u64, struct data_t); BPF_PERF_OUTPUT(events);
Nous enregistrons ici une table de hachage appelée
p , avec une clé de type
u64 et une valeur de type
struct data_t . Le tableau sera disponible dans le cadre de notre programme BPF. La macro BPF_PERF_OUTPUT enregistre une autre table appelée
événements , qui est utilisée pour
transférer des données vers l'espace utilisateur.
Lors de la mesure des retards entre un appel de fonction et son retour, ou entre des appels à différentes fonctions, il convient de garder à l'esprit que les données reçues doivent appartenir au même contexte. En d'autres termes, vous devez vous souvenir du lancement parallèle possible de fonctions. Nous avons la possibilité de mesurer le délai entre l'appel d'une fonction dans le contexte d'un processus et le retour de cette fonction dans le contexte d'un autre processus, mais cela est très probablement inutile. Un bon exemple ici est l'
utilitaire de biolatence , oĂą un pointeur vers une
demande de structure , qui reflète une seule
demande de disque, est défini comme clé dans la table de hachage.
Ensuite, nous devons écrire le code qui sera exécuté lorsque la fonction étudiée est appelée:
void start(struct pt_regs *ctx, struct bio *bio) { u64 pid = bpf_get_current_pid_tgid(); struct data_t data = {}; u64 ts = bpf_ktime_get_ns(); data.pid = pid; data.ts = ts; bpf_probe_read_str(&data.disk, sizeof(data.disk), (void*)bio->bi_disk->disk_name); p.update(&pid, &data); }
Ici, le deuxième argument de la fonction appelée
generic_make_request () sera remplacé comme deuxième argument. Après cela, nous obtenons le PID du processus dans lequel nous travaillons, et l'horodatage actuel en nanosecondes. Nous écrivons tout cela dans la
nouvelle structure struct data_t data . Nous obtenons le nom du disque de la structure
biologique , qui est transmis lors de l'appel de
generic_make_request () , et l'enregistrons dans la mĂŞme structure de
données . La dernière étape consiste à ajouter une entrée à la table de hachage mentionnée précédemment.
La fonction suivante sera appelée au retour de
generic_make_request () :
void stop(struct pt_regs *ctx) { u64 pid = bpf_get_current_pid_tgid(); u64 ts = bpf_ktime_get_ns(); struct data_t* data = p.lookup(&pid); if (data != 0 && data->ts > 0) { bpf_get_current_comm(&data->comm, sizeof(data->comm)); data->lat = (ts - data->ts)/1000; if (data->lat > MIN_US) { FACTOR data->pid >>= 32; events.perf_submit(ctx, data, sizeof(struct data_t)); } p.delete(&pid); } }
Cette fonction est similaire à la précédente: nous reconnaissons le PID et l'horodatage du processus, mais n'allouons pas de mémoire pour la nouvelle structure de données. Au lieu de cela, nous recherchons dans la table de hachage une structure existante avec la clé == PID actuel. Si la structure est trouvée, nous trouverons le nom du processus en cours et nous y ajouterons.
Le décalage binaire que nous utilisons ici est nécessaire pour obtenir le thread GID. c'est-à -dire Le PID du processus principal qui a démarré le thread dans le contexte duquel nous travaillons. La fonction
bpf_get_current_pid_tgid () que nous
appelons renvoie Ă la fois le GID du thread et son PID dans une valeur de 64 bits.
Lors de la sortie vers le terminal, nous ne sommes plus intéressés par le flux, mais par le processus principal. Après avoir comparé le retard reçu avec un seuil donné, nous transférons notre structure de
données vers l'espace utilisateur via la table des
événements , puis supprimons l'enregistrement de
p .
Dans le script python qui chargera ce code, nous devons remplacer MIN_US et FACTOR par les seuils de retard et les unités de temps, que nous passerons par les arguments:
bpf_text = bpf_text.replace('MIN_US',str(min_usec)) if args.milliseconds: bpf_text = bpf_text.replace('FACTOR','data->lat /= 1000;') label = "msec" else: bpf_text = bpf_text.replace('FACTOR','') label = "usec"
Maintenant, nous devons préparer le programme BPF via la
macro BPF et enregistrer les exemples:
b = BPF(text=bpf_text) b.attach_kprobe(event="generic_make_request",fn_name="start") b.attach_kretprobe(event="generic_make_request",fn_name="stop")
Nous devrons également définir
struct data_t dans notre script, sinon nous ne pourrons rien lire:
TASK_COMM_LEN = 16
La dernière étape est la sortie des données vers le terminal:
def print_event(cpu, data, size): global start event = ct.cast(data, ct.POINTER(Data)).contents if start == 0: start = event.ts time_s = (float(event.ts - start)) / 1000000000 print("%-18.9f %-16s %-6d %-1s %s %s" % (time_s, event.comm, event.pid, event.lat, label, event.disk)) b["events"].open_perf_buffer(print_event)
Le script lui-mĂŞme est disponible sur
GItHub . Essayons de l'exécuter sur une plate-forme de test où fio est écrit en bcache et appelons udevadm monitor:
Enfin! Nous voyons maintenant que ce qui ressemblait Ă un pĂ©riphĂ©rique bcache de freinage est en fait un appel de freinage Ă
generic_make_request () sur un lecteur mis en cache.
Creusez dans le noyau
Qu'est-ce qui ralentit exactement lors de la transmission de la demande? On voit que le retard intervient avant même le début de la comptabilisation de la demande, c'est-à -dire la prise en compte d'une demande spécifique de statistiques complémentaires (/ proc / diskstats ou iostat) n'a pas encore commencé. Cela peut être facilement vérifié en exécutant iostat tout en reproduisant le problème, ou le
script de biolatence BCC , qui est basé sur le début et la fin de la comptabilisation des demandes. Aucun de ces utilitaires ne présentera de problèmes pour les requêtes sur le lecteur mis en cache.
Si nous jetons un Ĺ“il Ă la fonction
generic_make_request () , nous verrons que deux fonctions supplémentaires sont appelées avant l'
enregistrement de la demande. Le premier,
generic_make_request_checks () , vérifie la légitimité d'une demande de paramètres de disque. Le second est
blk_queue_enter () , qui a un appel intĂ©ressant Ă
wait_event_interruptible () :
ret = wait_event_interruptible(q->mq_freeze_wq, (atomic_read(&q->mq_freeze_depth) == 0 && (preempt || !blk_queue_preempt_only(q))) || blk_queue_dying(q));
Dans celui-ci, le noyau attend le dégivrage de la file d'attente. Nous mesurons le retard
blk_queue_enter () :
~
Il semble que nous soyons proches d'une solution. Les fonctions utilisées pour «figer / dégeler» la file d'attente sont
blk_mq_freeze_queue et
blk_mq_unfreeze_queue . Ils sont utilisés lorsqu'il est nécessaire de modifier les paramètres de la file d'attente de requêtes, qui sont potentiellement dangereux pour les requêtes de cette file d'attente. Lorsque
blk_mq_freeze_queue () est appelé, la fonction
blk_freeze_queue_start () incrémente le
compteur q-> mq_freeze_depth . Après cela, le noyau attend la vidange de la file d'attente dans
blk_mq_freeze_queue_wait () .
Le temps d'attente pour effacer cette file d'attente équivaut à la latence du disque, car le noyau attend la fin de toutes les opérations en file d'attente. Dès que la file d'attente est vide, les modifications de paramètres sont appliquées. Ensuite,
blk_mq_unfreeze_queue () est appelé, décrémentant le compteur
freeze_depth .
Nous en savons maintenant assez pour rectifier la situation. La commande de déclenchement udevadm entraîne l'application de paramètres pour le périphérique de bloc. Ces paramètres sont décrits dans les règles udev. Nous pouvons savoir exactement quels paramètres «gèlent» la file d'attente en essayant de les modifier via sysfs ou en consultant le code source du noyau. Nous pouvons également essayer l'utilitaire de
trace BCC, qui affiche la
trace de la pile du noyau et de l'espace utilisateur pour le terminal pour chaque appel
blk_freeze_queue , par exemple:
~
Les règles Udev changent assez rarement et cela se produit généralement sous contrôle. Nous voyons donc que même l'utilisation de valeurs déjà définies entraîne une augmentation du délai de transmission de la demande de l'application au disque. Bien sûr, générer des événements udev lorsqu'il n'y a aucun changement dans la configuration du disque (par exemple, le périphérique ne se connecte / se déconnecte pas) n'est pas une bonne pratique. Cependant, nous pouvons aider le noyau à ne pas faire de travail inutile et à ne pas geler la file d'attente des requêtes si cela n'est pas nécessaire.
Trois petits commits corrigent la situation.
Conclusion
eBPF est un outil très flexible et puissant. Dans l'article, nous avons examiné un cas pratique et démontré une petite partie de ce qui est possible de faire. Si vous êtes intéressé par le développement des utilitaires BCC, vous devriez jeter un œil au
tutoriel officiel , qui décrit bien les bases.
Il existe d'autres outils de débogage et de profilage intéressants basés sur eBPF. L'un d'eux est
bpftrace , qui vous permet d'Ă©crire de puissants programmes Ă ligne unique et petits dans un langage de type awk. Un autre -
ebpf_exporter , vous permet de collecter des métriques de haute résolution de bas niveau directement dans votre serveur prometheus, avec la possibilité d'obtenir une belle visualisation et même des alertes à l'avenir.