Il existe de nombreux outils pour déboguer le noyau et les programmes de l'espace utilisateur sous Linux. La plupart d'entre eux ont un impact sur les performances et ne peuvent pas être exécutés facilement dans des environnements de production. Il y a quelques années, eBPF a
été développé , qui offre la possibilité de tracer le noyau et l'espace utilisateur avec une faible surcharge, sans avoir besoin de recompiler les programmes ou de charger les modules du noyau.
Il existe maintenant de nombreux outils qui utilisent eBPF et dans cet article, nous expliquerons comment écrire votre propre outil de profilage à l'aide de la
bibliothèque PythonBCC . Cet article est basé sur un vrai problème de l'environnement de production. Nous vous expliquerons comment résoudre le problème et montrerons comment les outils Cci existants pourraient être utilisés dans certains cas.
Ceph est lent
Une nouvelle plateforme a été ajoutée à un cluster ceph. Après la migration de certaines données vers la plate-forme, la latence des demandes d'écriture était plus élevée que sur les autres serveurs.
Cette plate-forme a un nouveau périphérique virtuel de mise en cache - bcache, que nous n'avions pas utilisé dans ce cluster auparavant - et un nouveau noyau - 4.15, qui n'est toujours pas utilisé ailleurs dans ce cluster. La racine du problème pourrait être n'importe où, alors examinons plus en profondeur.
Enquête sur l'hôte
Voyons ce qui se passe à l'intérieur du processus ceph-osd. Nous utilisons l'outil de traçage
perf et
flamescope pour construire des graphiques de flamme:
Comme nous pouvons le voir sur le graphique de flamme,
fdatasync () a passé beaucoup de temps à soumettre la bio dans la fonction
generic_make_request () . Ainsi, la racine de notre problème est quelque part en dehors du démon ceph. Il peut s'agir d'un problème de noyau, de bcache ou de disque. La sortie iostat a montré une latence élevée pour les périphériques bcache.
Une autre découverte suspecte est que le démon systemd-udevd consomme du CPU; environ 20% sur plusieurs processeurs. C'est un comportement étrange, nous devons donc savoir ce qui se passe. Puisque systemd-udevd fonctionne avec uevents, nous devons utiliser
udevadm monitor pour savoir s'il y a des uevents dans le système. Après vérification, nous avons vu que de nombreux événements de «changement» étaient générés pour chaque périphérique de bloc du système.
Ceci est inhabituel, nous allons donc découvrir ce qui provoque l'envoi de tous ces uevents.
Utilisation de la boîte à outils BCC
Comme nous le savons déjà, le noyau (et le démon ceph) passe beaucoup de temps à exécuter les fonctions
generic_make_requst () .
Mesurons sa latence en utilisant
funclatency à partir de la
boîte à outils BCC , juste pour nous assurer que nous sommes sur la bonne voie. Nous tracerons le PID du démon ceph (argument -p) à des intervalles de 1 seconde (-i) et afficherons la latence en millisecondes (-m).
Cette fonction fonctionne généralement très rapidement. Tout ce qu'il fait est de soumettre la structure biologique à la file d'attente du pilote de périphérique.
Bcache est un appareil complexe; en fait, il se compose de 3 appareils: un support, qui est un disque dur lent dans notre cas; un périphérique de mise en cache, qui est la partition du lecteur NVMe; et un périphérique virtuel bcache, qui est utilisé par l'application. Nous savons que la soumission est lente, mais pour quel appareil? C'est quelque chose que nous verrons un peu plus tard.
Pour l'instant, nous savons que les uevents causent des problèmes dans les démons ceph et nous devons trouver le logiciel déclenchant les uevents. Il n'est pas facile de trouver ce qui provoque leur génération. Nous supposons que c'est un logiciel qui ne fonctionne que périodiquement. Pour voir ce qui est exécuté sur le système, nous utilisons
execsnoop de la boîte à outils BCC. Nous pouvons l'exécuter et rediriger
stdout vers un fichier.
Par exemple:
/usr/share/bcc/tools/execsnoop | tee ./execdump
Nous ne donnerons pas la sortie execsnoop complète ici, mais nous avons trouvé une chaîne intéressante:
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 du processus. Nous avons vérifié ce qu'était le 5802 et avons vu qu'il s'agissait de l'un de nos threads de démon de surveillance. En regardant plus loin la configuration du système de surveillance, nous avons trouvé un paramètre défectueux. La température du HBA était récupérée toutes les 30 secondes, ce qui est trop souvent. Après avoir modifié l'intervalle de vérification à une valeur plus appropriée, nous avons vu que notre latence ceph correspondait aux autres plates-formes.
Mais nous ne savons toujours pas pourquoi la latence bcache était élevée. Nous avons mis en place une plate-forme de test avec la même configuration et essayé de reproduire le problème avec fio sur le périphérique bcache tout en déclenchant simultanément udev avec la commande udevadm trigger.
Écriture d'outils basés sur BCC
Ce que nous allons faire ici, c'est écrire un outil simple qui trace les appels generic_make_request () les plus lents et affiche le nom du disque pour lequel la fonction a été appelée.
Le plan est simple:
- Enregistrez kprobe sur generic_make_request () :
- Enregistrez le nom du disque disponible à partir de l'argument de la fonction
- Enregistrer l'horodatage actuel
- Enregistrez kretprobe sur l' instruction de retour generic_make_request () :
- Récupérer l'horodatage actuel
- Recherchez les horodatages précédemment enregistrés et comparez-les avec ceux actuels
- Si le résultat est supérieur au seuil, recherchez les noms de disque précédemment enregistrés et imprimez-les sur le terminal avec des informations supplémentaires
Kprobes et
kretprobes utilisent des points d'arrêt pour modifier le code d'une fonction lors de l'exécution. Vous pouvez trouver de la
documentation ainsi qu'un bon
article à ce sujet. Si vous regardez le code des différents
outils BCC , vous verrez qu'ils ont tous une structure identique. Nous allons ignorer l'analyse des arguments et nous concentrer sur le programme BPF lui-même.
Le texte de notre programme sera défini en python comme suit:
bpf_text = “””
Les programmes BPF utilisent des
hashmaps pour partager des données entre différentes fonctions. Nous utiliserons le PID comme clé et la structure auto-définie comme valeur.
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);
Ici, nous enregistrons une table de hachage appelée
p avec un type de clé
u64 et un type de valeur
struct data_t . Cette carte est accessible à partir de notre contexte de programme BPF. La macro
BPF_PERF_OUTPUT enregistre une autre carte appelée
événements , qui est utilisée pour
pousser les données vers l'espace utilisateur.
Lorsque vous mesurez la latence entre l'appel de fonction et son retour ou entre un appel de fonction et un autre, vous devez vous assurer que les données que vous avez enregistrées et auxquelles vous accédez ultérieurement se rapportent au même contexte. En d'autres termes, vous devez être conscient de toute autre exécution parallèle de la même fonction. Il est possible de tracer la latence entre l'appel de fonction d'un processus et les retours de la même fonction d'un autre processus, mais cela ne nous aide pas. Un bon exemple est l'
outil de biolatence où le pointeur vers la
demande de structure est utilisé comme clé de hachage.
Ensuite, nous devons écrire un code qui sera exécuté lors des appels de fonction via un mécanisme kprobe:
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, nous avons le premier
argument generic_make_request () comme deuxième argument de notre fonction. Ensuite, nous obtenons le PID et l'horodatage actuel en nanosecondes et l'écrivons dans les
données struct data_t nouvellement allouées. Nous obtenons le nom du disque de la structure biologique, qui est passé à
generic_make_request () , et l'enregistrons dans nos
données . La dernière étape consiste à ajouter une entrée à la table de hachage que nous avons décrite précédemment.
Cette fonction sera exécutée sur les
retours 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); } }
Nous obtenons le PID et l'horodatage de la sortie précédente et recherchons la table de hachage pour la valeur où
clé == PID actuel . S'il est trouvé, nous obtenons le nom du processus en cours et l'ajoutons à la structure de
données . Ce que nous faisons avec
data-> pid ici nous donne l'ID du groupe de threads. La
fonction bpf_get_current_pid_tgid () précédemment appelée renvoie le thread GID et PID du processus dans la même valeur 64 bits.
Nous ne sommes pas intéressés par l'ID de chaque thread, mais nous voulons connaître le PID du thread principal. Après avoir vérifié que la latence est supérieure au seuil, nous soumettons notre structure de
données à l'espace utilisateur via la carte des
événements , puis supprimons l'entrée de la table de hachage à la fin.
Dans notre script python, nous devons remplacer
MIN_US et
FACTOR selon le seuil que nous voulons et l'unité de temps que nous voulons voir dans notre résultat:
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"
Ensuite, nous devons préparer le programme BPF avec une
macro BPF () et enregistrer les sondes:
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 devons également définir la même structure que
struct data_t dans notre script pour lire les données du programme BPF:
TASK_COMM_LEN = 16
La dernière étape consiste à imprimer les données que nous voulons:
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 complet est disponible sur
GitHub . Exécutons le script et déclenchons les événements udev pendant que fio écrit sur un périphérique bcache:
Succès! Nous voyons maintenant que ce qui ressemblait à une latence élevée pour bcache est vraiment
une latence
generic_make_request () pour son périphérique de support.
Creusez dans le noyau
Qu'est-ce qui traîne lors de la soumission des demandes? Nous constatons qu'un pic de latence s'est produit avant même que la comptabilité des demandes ne démarre. Cela pourrait être facilement vérifié en exécutant iostat pendant le problème ou le
script BCC de biolatence , qui sont basés sur le démarrage de la demande de comptabilité, donc aucun outil n'affichera le problème du disque.
Si nous jetons un œil à
generic_make_request () , nous voyons qu'il y a deux fonctions en cours d'exécution avant le début de la comptabilité. Le premier est
generic_make_request_checks () , qui est léger et vérifie la bio en fonction des paramètres de l'appareil, etc. Le second est
blk_queue_enter () , qui a un appel
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));
Ici, le noyau attend que la file d'attente soit libérée. Mesurons la latence de blk_queue_enter ():
~
On dirait que nous sommes proches. Les fonctions utilisées pour geler / dégeler la file d'attente sont
blk_mq_freeze_queue et
blk_mq_unfreeze_queue . Ils sont utilisés pour modifier les paramètres de file d'attente, ce qui pourrait affecter les demandes io actuellement en cours. Lorsque
blk_mq_freeze_queue () est appelé,
q-> mq_freeze_depth est incrémenté dans
blk_freeze_queue_start () . Après cela, le noyau attend que la file d'attente soit vide dans
blk_mq_freeze_queue_wait () .
Ce temps d'attente est égal à la latence du disque, car le noyau doit attendre la fin de toutes les opérations io. Lorsque la file d'attente est vide, des modifications peuvent être apportées. La dernière étape consiste à appeler
blk_mq_unfreeze_queue () , ce qui diminue le compteur
freeze_depth .
Nous en savons maintenant suffisamment pour résoudre le problème. La commande de déclenchement udevadm modifie les paramètres des périphériques de bloc. Ces paramètres sont décrits dans les règles udev. Nous pouvons découvrir quels paramètres gèlent la file d'attente en les modifiant via sysfs ou en consultant le code source du noyau. Alternativement, nous pouvons
appeler trace à partir de la boîte à outils BCC pour imprimer les piles de noyau et d'utilisateur pour chaque appel
blk_freeze_queue :
~
Les règles Udev ne changent pas souvent, donc même l'attribution de valeurs déjà existantes à certains paramètres provoque un pic de latence de soumission pour l'application. Bien sûr, générer des événements udev lorsqu'il n'y a aucun changement dans la configuration d'un périphérique (aucun périphérique n'est connecté ou détaché) n'est pas une bonne pratique. Néanmoins, nous pouvons empêcher le noyau de geler la file d'attente s'il n'y a aucune raison de le faire.
Trois petits commits résolvent le problème.
Conclusion
eBPF est un instrument très flexible et puissant. Dans cet article, nous avons examiné un seul cas et démontré un peu de ses capacités. Si vous êtes intéressé par le développement d'outils basés sur BCC, vous devriez jeter un œil au
didacticiel officiel , qui décrit ses concepts fondamentaux.
Il existe également d'autres outils intéressants basés sur eBPF disponibles pour le profilage et le débogage. L'un d'eux est
bpftrace , qui vous permet d'écrire de puissants oneliners et de petits programmes dans un langage de type awk. Un autre est
ebpf_exporter , qui peut collecter des mesures de haute résolution de bas niveau sur votre serveur prometheus avec ses excellentes capacités de visualisation et d'alerte.