Linux dispose d'un grand nombre d'outils pour déboguer le noyau et les applications. La plupart d’entre eux ont un impact négatif sur les performances des applications et ne peuvent pas être utilisés en production.
Il y a quelques années, il y avait - eBPF. Il permet de tracer le noyau et les applications utilisateur avec une faible surcharge et sans avoir besoin de reconstruire les 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 votre propre utilitaire de profilage basé sur la bibliothèque. . L'article est basé sur des événements réels. Nous passerons du problème à la résolution 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é une partie des données vers celui-ci, nous avons remarqué que la vitesse de traitement des demandes d'écriture par celui-ci était bien inférieure à celle des autres serveurs.
Contrairement à d'autres plates-formes, cet hôte utilisait bcache et le nouveau noyau Linux 4.15. C'était la première fois qu'un hôte de cette configuration était utilisé ici. Et à ce moment-là, il était clair que la racine du problème pouvait théoriquement être n’importe quoi.
Enquête sur l'hôte
Commençons par examiner ce qui se passe au sein du processus ceph-osd. Pour cela nous utiliserons и (plus d'informations sur lesquelles vous pouvez lire ):
L'image nous dit que la fonction fdatasync() passé beaucoup de temps à envoyer une requête aux fonctions générique_make_request(). Cela signifie que la cause des problèmes se situe très probablement quelque part en dehors du démon osd lui-même. Cela peut être soit le noyau, soit les disques. La sortie d'iostat a montré une latence élevée dans le traitement des requêtes par les 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 découvrir pourquoi. Puisque Systemd-udevd fonctionne avec uevents, nous avons décidé de les examiner via moniteur udevadm. Il s'avère qu'un grand nombre d'événements de changement ont été générés pour chaque périphérique bloc du système. C’est assez inhabituel, il va donc falloir regarder 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 à générique_make_request(). Essayons de mesurer la vitesse de cette fonction. DANS Il existe déjà un merveilleux utilitaire - fonctionnalité. Nous tracerons le démon par son PID avec un intervalle de 1 seconde entre les sorties et afficherons le résultat en millisecondes.
Cette fonctionnalité fonctionne généralement rapidement. Tout ce qu'il fait, c'est transmettre la demande à la file d'attente du pilote de périphérique.
Cache est un périphérique complexe composé en réalité 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), ici il s'agit d'une partition du périphérique NVMe ;
- le périphérique virtuel bcache avec lequel l'application s'exécute.
Nous savons que la transmission des requêtes est lente, mais pour lequel de ces appareils ? Nous y reviendrons un peu plus tard.
Nous savons désormais que les événements sont susceptibles de causer des problèmes. Trouver la cause exacte de leur génération n’est pas si facile. Supposons qu'il s'agisse d'une sorte de logiciel lancé périodiquement. Voyons quel type de logiciel s'exécute sur le système à l'aide d'un script execsnoop du même . Exécutons-le et envoyons la sortie dans un fichier.
Par exemple, comme ceci:
/usr/share/bcc/tools/execsnoop | tee ./execdump
Nous ne montrerons pas ici le résultat complet d’execsnoop, mais une ligne qui nous intéresse 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 conducteurs 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 toutes les 30 secondes, ce qui est bien plus souvent que nécessaire. Après avoir modifié l'intervalle de vérification pour un intervalle plus long, nous avons constaté que la latence de traitement des requêtes sur cet hôte ne se démarquait plus de celle des autres hôtes.
Mais on ne sait toujours pas pourquoi le périphérique bcache était si lent. Nous avons préparé une plateforme de test avec une configuration identique et essayé de reproduire le problème en exécutant fio sur bcache, en exécutant périodiquement le déclencheur udevadm pour générer des uevents.
Écriture d'outils basés sur BCC
Essayons d'écrire un utilitaire simple pour tracer et afficher les appels les plus lents générique_make_request(). Nous nous intéressons également au nom du lecteur pour lequel cette fonction a été appelée.
Le planning est simple :
- Registre kprobe sur générique_make_request():
- Nous sauvegardons le nom du disque en mémoire, accessible via l'argument de la fonction ;
- Nous enregistrons l'horodatage.
- Registre sonde à kret pour le retour de générique_make_request():
- Nous obtenons l'horodatage actuel ;
- Nous recherchons l'horodatage enregistré et le comparons avec l'horodatage actuel ;
- Si le résultat est supérieur à celui spécifié, nous trouvons le nom du disque enregistré et l'affichons sur le terminal.
Ksondes и sondes à kret utilisez un mécanisme de point d'arrêt pour modifier le code de fonction à la volée. Tu peux lire и article sur ce sujet. Si vous regardez le code de divers utilitaires dans , alors vous pouvez voir qu’ils ont une structure identique. Ainsi, dans cet article, nous allons ignorer l'analyse des arguments du script et passer au programme BPF lui-même.
Le texte eBPF à l'intérieur du script Python ressemble à ceci :
bpf_text = “”” # Here will be the bpf program code “””
Pour échanger des données entre fonctions, les programmes eBPF utilisent . Nous ferons de même. Nous utiliserons le PID du processus comme clé et définirons la structure 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 type de clé u64 et une valeur de type structure 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é pour dans l’espace utilisateur.
Lorsque vous mesurez les délais entre l'appel d'une fonction et son retour, ou entre les appels à différentes fonctions, vous devez tenir compte du fait que les données reçues doivent appartenir au même contexte. En d’autres termes, il faut penser à l’éventuel lancement parallèle de fonctions. Nous avons la possibilité de mesurer la latence 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 probablement inutile. Un bon exemple ici serait , où la clé de la table de hachage est définie sur un pointeur vers demande de structure, qui reflète une demande de disque.
Ensuite, nous devons écrire le code qui s'exécutera lorsque la fonction étudiée sera 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 premier argument de la fonction appelée sera remplacé comme deuxième argument . Après cela, nous obtenons le PID du processus dans le contexte duquel nous travaillons, ainsi que l'horodatage actuel en nanosecondes. Nous écrivons tout cela dans un format fraîchement sélectionné struct data_t données. Nous obtenons le nom du disque à partir de la structure bio, qui est transmis lors de l'appel générique_make_request(), et enregistrez-le dans la même structure 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 générique_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 : on connaît le PID du processus et l'horodatage, mais n'alloue pas de mémoire pour la nouvelle structure de données. Au lieu de cela, nous recherchons dans la table de hachage une structure déjà existante en utilisant la clé == PID actuel. Si la structure est trouvée, nous découvrons le nom du processus en cours et l'y ajoutons.
Le décalage binaire que nous utilisons ici est nécessaire pour obtenir le GID du thread. ceux. PID du processus principal qui a démarré le thread dans le cadre duquel nous travaillons. La fonction que nous appelons renvoie à la fois le GID du thread et son PID dans une seule valeur de 64 bits.
Lors de la sortie vers le terminal, nous ne sommes actuellement pas intéressés par le thread, mais nous nous intéressons au processus principal. Après avoir comparé le retard résultant avec un seuil donné, nous transmettons notre structure données dans l'espace utilisateur via une table événements, après quoi nous supprimons l'entrée 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 en 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"
Il nous faut maintenant préparer le programme BPF via et enregistrer des échantillons :
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")
Il faudra également déterminer structure data_t dans notre script, sinon nous ne pourrons rien lire :
TASK_COMM_LEN = 16 # linux/sched.h
DISK_NAME_LEN = 32 # linux/genhd.h
class Data(ct.Structure):
_fields_ = [("pid", ct.c_ulonglong),
("ts", ct.c_ulonglong),
("comm", ct.c_char * TASK_COMM_LEN),
("lat", ct.c_ulonglong),
("disk",ct.c_char * DISK_NAME_LEN)]
La dernière étape consiste à envoyer les données au 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)
# format output
start = 0
while 1:
try:
b.perf_buffer_poll()
except KeyboardInterrupt:
exit()
Le script lui-même est disponible sur . Essayons de l'exécuter sur une plate-forme de test sur laquelle fio s'exécute, écrit dans bcache et appelons udevadm monitor :
Enfin! Nous voyons maintenant que ce qui ressemblait à un périphérique bcache bloqué est en réalité un appel bloqué. générique_make_request() pour un disque mis en cache.
Creusez dans le noyau
Qu'est-ce qui ralentit exactement pendant la transmission des requêtes ? On voit que le retard se produit avant même le début de la comptabilisation des demandes, c'est-à-dire la prise en compte d'une demande spécifique de production ultérieure de statistiques sur celui-ci (/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 , qui est basé sur le début et la fin de la comptabilité des demandes. Aucun de ces utilitaires ne présentera de problèmes pour les requêtes sur le disque mis en cache.
Si l'on regarde la fonction générique_make_request(), nous verrons alors qu'avant que la requête ne commence la comptabilité, deux autres fonctions sont appelées. D'abord - générique_make_request_checks(), effectue des vérifications sur la légitimité de la demande concernant les paramètres du disque. Deuxième - , qui présente un défi intéressant :
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 que la file d'attente se débloque. Mesurons le retard blk_queue_enter():
~# /usr/share/bcc/tools/funclatency blk_queue_enter -i 1 -m
Tracing 1 functions for "blk_queue_enter"... Hit Ctrl-C to end.
msecs : count distribution
0 -> 1 : 341 |****************************************|
msecs : count distribution
0 -> 1 : 316 |****************************************|
msecs : count distribution
0 -> 1 : 255 |****************************************|
2 -> 3 : 0 | |
4 -> 7 : 0 | |
8 -> 15 : 1 | |
Il semble que nous soyons proches d’une solution. Les fonctions utilisées pour geler/dégeler une file d'attente sont и . Ils sont utilisés lorsqu'il est nécessaire de modifier les paramètres de la file d'attente des requêtes, qui sont potentiellement dangereux pour les requêtes de cette file d'attente. En appelant blk_mq_freeze_queue() функцией le compteur est incrémenté q->mq_freeze_profondeur. Après cela, le noyau attend que la file d'attente se vide .
Le temps nécessaire 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. Une fois la file d'attente vide, les modifications des paramètres sont appliquées. Après quoi on l'appelle , décrémentant le compteur gel_profondeur.
Nous en savons désormais suffisamment pour corriger la situation. La commande udevadm trigger entraîne l'application des paramètres du périphérique de blocage. Ces paramètres sont décrits dans les règles udev. Nous pouvons trouver les paramètres qui 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 BCC , qui affichera des traces du noyau et de la pile d'espace utilisateur pour chaque appel au terminal blk_freeze_queue, Par exemple:
~# /usr/share/bcc/tools/trace blk_freeze_queue -K -U
PID TID COMM FUNC
3809642 3809642 systemd-udevd blk_freeze_queue
blk_freeze_queue+0x1 [kernel]
elevator_switch+0x29 [kernel]
elv_iosched_store+0x197 [kernel]
queue_attr_store+0x5c [kernel]
sysfs_kf_write+0x3c [kernel]
kernfs_fop_write+0x125 [kernel]
__vfs_write+0x1b [kernel]
vfs_write+0xb8 [kernel]
sys_write+0x55 [kernel]
do_syscall_64+0x73 [kernel]
entry_SYSCALL_64_after_hwframe+0x3d [kernel]
__write_nocancel+0x7 [libc-2.23.so]
[unknown]
3809631 3809631 systemd-udevd blk_freeze_queue
blk_freeze_queue+0x1 [kernel]
queue_requests_store+0xb6 [kernel]
queue_attr_store+0x5c [kernel]
sysfs_kf_write+0x3c [kernel]
kernfs_fop_write+0x125 [kernel]
__vfs_write+0x1b [kernel]
vfs_write+0xb8 [kernel]
sys_write+0x55 [kernel]
do_syscall_64+0x73 [kernel]
entry_SYSCALL_64_after_hwframe+0x3d [kernel]
__write_nocancel+0x7 [libc-2.23.so]
[unknown]
Les règles Udev changent assez rarement et cela se produit généralement de manière contrôlée. Nous constatons donc que même l'application des valeurs déjà définies provoque une augmentation du délai de transfert de la requête de l'application vers le disque. Bien entendu, 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 n'est pas monté/déconnecté) n'est pas une bonne pratique. Cependant, nous pouvons aider le noyau à ne pas effectuer de travail inutile et à geler la file d'attente des requêtes si cela n'est pas nécessaire. corriger la situation.
Conclusion
eBPF est un outil très flexible et puissant. Dans cet article, nous avons examiné un cas pratique et démontré une petite partie de ce qui peut être fait. Si vous souhaitez développer des utilitaires BCC, cela vaut la peine de jeter un œil à , 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 - , qui vous permet d'écrire de puissants one-liners et de petits programmes dans un langage de type awk. Un autre - , vous permet de collecter des métriques de bas niveau et haute résolution directement sur votre serveur Prometheus, avec la possibilité d'obtenir ultérieurement de superbes visualisations et même des alertes.
Source: habr.com