Il existe de nombreux outils sous Linux pour le dĂ©bogage des noyaux et des 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, un nouvel outil a été développé Il existe maintenant de nombreux utilitaires applicatifs qui utilisent eBPF, et dans cet article, nous verrons comment écrire notre propre utilitaire de profilage basé sur la bibliothÚque
PythonBCC Ceph est lent
Un nouvel hĂŽte a Ă©tĂ© ajoutĂ© au cluster Ceph. AprĂšs la migration d'une partie des donnĂ©es vers celui-ci, nous avons remarquĂ© que la vitesse de traitement des requĂȘtes d'Ă©criture Ă©tait bien infĂ©rieure Ă celle des autres serveurs.
Contrairement aux autres plateformes, cet hĂŽte utilisait bcache et un nouveau noyau Linux 4.15. Ce type de configuration Ă©tait utilisĂ© ici pour la premiĂšre fois. Ă ce moment-lĂ , il Ă©tait clair que le problĂšme pouvait thĂ©oriquement provenir de n'importe oĂč.
EnquĂȘte sur l'hĂŽte
Commençons par examiner ce qui se passe à l'intérieur du processus ceph-osd. Pour ce faire, nous utiliserons
flamescope et L'image nous indique que la fonction ):
a passĂ© beaucoup de temps Ă envoyer des requĂȘtes Ă la fonction fdatasync() generic_make_request() . Cela signifie que la cause des problĂšmes se trouve probablement en dehors du dĂ©mon osd lui-mĂȘme. Cela pourrait ĂȘtre soit le noyau, soit les disques. La sortie de iostat montrait une forte latence dans le traitement des requĂȘtes par les disques bcache.En vĂ©rifiant l'hĂŽte, nous avons dĂ©couvert que le dĂ©mon systemd-udevd consommait beaucoup de temps CPU â environ 20 % sur plusieurs cĆurs. Ce comportement Ă©trange nĂ©cessite une enquĂȘte. Puisque Systemd-udevd travaille avec des uevent, nous avons dĂ©cidĂ© de les observer Ă travers
udevadm monitor . Il s'avÚre qu'un grand nombre d'événements de changement étaient générés pour chaque périphérique de bloc dans le systÚme. Cela semble assez inhabituel, donc nous devrons déterminer ce qui génÚre tous ces événements.Utilisation de l'outil BCC
Comme nous l'avons découvert, le noyau (et le démon ceph dans l'appel systÚme) consomme beaucoup de temps dans
. Essayons de mesurer la vitesse d'exĂ©cution de cette fonction. Il existe dĂ©jĂ un excellent utilitaire â . Cela signifie que la cause des problĂšmes se trouve probablement en dehors du dĂ©mon osd lui-mĂȘme. Cela pourrait ĂȘtre soit le noyau, soit les disques. La sortie de iostat montrait une forte latence dans le traitement des requĂȘtes par les disques bcache.funclatency il existe dĂ©jĂ un excellent utilitaire â funclatency. Nous allons tracer le dĂ©mon par son PID avec un intervalle d'affichage d'une seconde et afficher le rĂ©sultat en millisecondes.
Cette fonction fonctionne gĂ©nĂ©ralement rapidement. Tout ce qu'elle fait est de transmettre la requĂȘte dans la file d'attente du pilote du pĂ©riphĂ©rique.
Bcache est un dispositif complexe qui se compose en réalité de trois disques :
- dispositif de sauvegarde (disque mis en cache), dans ce cas un HDD lent ;
- dispositif de mise en cache (disque de cache), ici un partition NVMe de l'appareil ;
- un dispositif virtuel bcache, avec lequel l'application travaille.
Nous savons que la transmission de la requĂȘte se bloque, mais pour lequel de ces dispositifs ? Nous allons examiner cela un peu plus tard.
Pour l'instant, nous savons que les uevents sont probablement Ă l'origine des problĂšmes. Trouver ce qui cause leur gĂ©nĂ©ration n'est pas si simple. Supposons que ce soit un logiciel qui s'exĂ©cute pĂ©riodiquement. Regardons quel logiciel est exĂ©cutĂ© dans le systĂšme Ă l'aide du script execsnoop du mĂȘme . ExĂ©cutons-le et dirigeons la sortie vers un fichier.
Par exemple comme ceci :
/usr/share/bcc/tools/execsnoop | tee ./execdump
Nous ne fournirons pas ici la sortie complÚte 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 un des threads de notre systĂšme de surveillance. Lors de la vĂ©rification de la configuration du systĂšme de surveillance, des paramĂštres incorrectement dĂ©finis ont Ă©tĂ© trouvĂ©s. La tempĂ©rature de l'adaptateur HBA Ă©tait mesurĂ©e toutes les 30 secondes, ce qui est beaucoup trop frĂ©quent. AprĂšs avoir modifiĂ© l'intervalle de vĂ©rification pour un plus long, nous avons constatĂ© que le retard dans le traitement des requĂȘtes de cet hĂŽte ne se distinguait plus des autres hĂŽtes.
Mais il reste encore à comprendre pourquoi le dispositif bcache était si lent. Nous avons préparé une plateforme de test avec une configuration identique et avons essayé de reproduire le problÚme en exécutant fio sur bcache, en lançant périodiquement udevadm trigger pour générer des uevents.
Ăcrire des outils basĂ©s sur BCC
Essayons d'Ă©crire un utilitaire simple pour tracer et afficher Ă l'Ă©cran les appels les plus lents . Cela signifie que la cause des problĂšmes se trouve probablement en dehors du dĂ©mon osd lui-mĂȘme. Cela pourrait ĂȘtre soit le noyau, soit les disques. La sortie de iostat montrait une forte latence dans le traitement des requĂȘtes par les disques bcache.. Nous sommes Ă©galement intĂ©ressĂ©s par le nom du disque pour lequel cette fonction a Ă©tĂ© appelĂ©e.
Le plan est simple :
- Enregistrement kprobe sur . Cela signifie que la cause des problĂšmes se trouve probablement en dehors du dĂ©mon osd lui-mĂȘme. Cela pourrait ĂȘtre soit le noyau, soit les disques. La sortie de iostat montrait une forte latence dans le traitement des requĂȘtes par les disques bcache.:
- Nous sauvegardons en mémoire le nom du disque accessible via l'argument de la fonction ;
- Nous sauvegardons le timestamp.
- Enregistrement kretprobe au retour de . Cela signifie que la cause des problĂšmes se trouve probablement en dehors du dĂ©mon osd lui-mĂȘme. Cela pourrait ĂȘtre soit le noyau, soit les disques. La sortie de iostat montrait une forte latence dans le traitement des requĂȘtes par les disques bcache.:
- Nous obtenons le timestamp actuel ;
- Nous cherchons le timestamp sauvegardé et le comparons avec le courant ;
- Si le résultat est supérieur à celui indiqué, nous trouvons le nom du disque enregistré et l'affichons dans le terminal.
Kprobes et kretprobes utilisent un mĂ©canisme de points d'arrĂȘt pour modifier le code des fonctions Ă la volĂ©e. Vous pouvez lire et article Ă ce sujet. Si l'on regarde le code de divers utilitaires dans , on peut remarquer qu'ils ont une structure identique. Dans cet article, nous omettrons donc l'analyse des arguments du script et passerons directement au programme BPF.
Le texte eBPF dans le script python ressemble Ă ceci :
bpf_text = """ # Ici sera le code du programme bpf """
Pour Ă©changer des donnĂ©es entre les fonctions, les programmes eBPF utilisent . Nous allons faire de mĂȘme. 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);
Ici, nous enregistrons une table de hachage appelée p, avec une clé de type u64 et une valeur de type struct data_t. La table sera accessible dans le contexte de notre programme BPF. Le macro BPF_PERF_OUTPUT enregistre une autre table appelée events, qui est utilisée pour vers l'espace utilisateur.
Lors de la mesure des dĂ©lais entre l'appel d'une fonction et son retour, ou entre les appels de diffĂ©rentes fonctions, il faut prendre en compte le fait que les donnĂ©es obtenues doivent appartenir Ă un mĂȘme contexte. En d'autres termes, il faut se souvenir des possibles exĂ©cutions en parallĂšle des 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 sera probablement inutile. Un bon exemple ici peut ĂȘtre , oĂč comme clĂ© de la table de hachage, on utilise un pointeur sur struct request, qui reflĂšte une seule requĂȘte au disque.
Ensuite, nous devons écrire le code qui sera exécuté lors de l'appel de la fonction étudié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 sera remplacĂ© par le premier argument de la fonction appelĂ©e . AprĂšs cela, nous obtenons le PID du processus dans le contexte duquel nous travaillons, ainsi que le timestamp actuel en nanosecondes. Nous enregistrons tout cela dans un nouvel struct data_t data. Le nom du disque est obtenu Ă partir de la structure bio, qui est transmis lors de l'appel . Cela signifie que la cause des problĂšmes se trouve probablement en dehors du dĂ©mon osd lui-mĂȘme. Cela pourrait ĂȘtre soit le noyau, soit les disques. La sortie de iostat montrait une forte latence dans le traitement des requĂȘtes par les disques bcache., et nous le conservons dans la mĂȘme structure data. La derniĂšre Ă©tape consiste Ă ajouter une entrĂ©e dans la table de hachage mentionnĂ©e prĂ©cĂ©demment.
La fonction suivante sera appelĂ©e Ă la sortie de . Cela signifie que la cause des problĂšmes se trouve probablement en dehors du dĂ©mon osd lui-mĂȘme. Cela pourrait ĂȘtre soit le noyau, soit les disques. La sortie de iostat montrait une forte latence dans le traitement des requĂȘtes par les disques bcache.:
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 obtenons le PID du processus et le timestamp, mais nous n'allouons pas de mémoire pour une nouvelle structure de données. Au lieu de cela, nous cherchons dans la table de hachage une structure existante avec la clé == le PID actuel. Si la structure est trouvée, nous obtenons le nom du processus en cours d'exécution et l'ajoutons à celle-ci.
Le décalage binaire que nous utilisons ici est nécessaire pour obtenir le GID de thread, c'est-à -dire le PID du processus principal qui a lancé le thread, dans le contexte duquel nous travaillons. La fonction que nous appelons renvoie à la fois le GID du thread et son PID dans une seule valeur 64 bits.
Lors de l'affichage dans le terminal, nous ne nous intéressons pas actuellement au thread, mais au processus principal. AprÚs avoir comparé la latence obtenue avec le seuil donné, nous transmettons notre structure data à l'espace utilisateur via la table events, 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 latence et d'unités de temps que nous transmettrons via des 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"
Nous devons maintenant préparer le programme BPF via et enregistrer les probes :
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 # 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 à afficher les données dans 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)
# 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 plateforme de test oĂč fio est en cours d'exĂ©cution, Ă©crivant sur bcache, et d'appeler udevadm monitor :
Enfin ! Maintenant nous voyons que ce qui semblait ĂȘtre un dispositif bcache ralentissant est en rĂ©alitĂ© un appel de ralentissement . Cela signifie que la cause des problĂšmes se trouve probablement en dehors du dĂ©mon osd lui-mĂȘme. Cela pourrait ĂȘtre soit le noyau, soit les disques. La sortie de iostat montrait une forte latence dans le traitement des requĂȘtes par les disques bcache. pour le disque mis en cache.
Analysez le noyau
Qu'est-ce qui ralentit exactement lors de la transmission de la requĂȘte ? Nous voyons que le dĂ©lai survient mĂȘme avant le dĂ©but de la comptabilitĂ© de la requĂȘte, c'est-Ă -dire que le comptage spĂ©cifique de la requĂȘte pour une sortie statistique ultĂ©rieure ( /proc/diskstats ou iostat ) n'a pas encore commencĂ©. Il est facile de vĂ©rifier cela en exĂ©cutant iostat pendant la reproduction du problĂšme, ou , qui se base sur le dĂ©but et la fin de la comptabilitĂ© des requĂȘtes. Aucune de ces utilitaires ne montrera de problĂšmes pour les requĂȘtes vers le disque mis en cache.
Si nous regardons la fonction . Cela signifie que la cause des problĂšmes se trouve probablement en dehors du dĂ©mon osd lui-mĂȘme. Cela pourrait ĂȘtre soit le noyau, soit les disques. La sortie de iostat montrait une forte latence dans le traitement des requĂȘtes par les disques bcache., nous verrons qu'avant le dĂ©but de la comptabilitĂ© de la requĂȘte, deux autres fonctions sont appelĂ©es. La premiĂšre â generic_make_request_checks(), effectue des vĂ©rifications de la lĂ©gitimitĂ© de la requĂȘte par rapport aux paramĂštres du disque. La seconde â , qui contient un appel 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 celle-ci, le noyau attend le dégel de la file d'attente. Mesurons le délai blk_queue_enter():
~# /usr/share/bcc/tools/funclatency blk_queue_enter -i 1 -m
Traçage de 1 fonction pour "blk_queue_enter"... Appuyez sur Ctrl-C pour terminer.
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 de la solution. Les fonctions utilisĂ©es pour "geler/dĂ©geler" la file d'attente sont et . Elles sont utilisĂ©es lorsqu'il est nĂ©cessaire de modifier les paramĂštres de la file d'attente des requĂȘtes, susceptibles d'affecter les requĂȘtes en cours dans cette file d'attente. Lors de l'appel de blk_mq_freeze_queue() par la fonction le compteur q->mq_freeze_depth. Ensuite, le noyau attend que la file soit vidĂ©e dans .
Le temps d'attente pour vider cette file est équivalent au délai du disque, car le noyau attend l'achÚvement de toutes les opérations en file d'attente. DÚs que la file est vide, les paramÚtres sont appliqués. Ensuite, on appelle , qui décrémente le compteur freeze_depth.
Nous savons maintenant assez de choses pour corriger la situation. La commande udevadm trigger entraßne l'application des paramÚtres pour le périphérique de bloc. Ces paramÚtres sont décrits dans les rÚgles udev. Nous pouvons identifier quels paramÚtres « gÚlent » la file en essayant de les modifier via sysfs ou en consultant le code source du noyau. Nous pouvons également essayer l'outil BCC , qui affichera dans le terminal les traces de pile du noyau et de l'espace utilisateur pour chaque appel à 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 [noyau]
elevator_switch+0x29 [noyau]
elv_iosched_store+0x197 [noyau]
queue_attr_store+0x5c [noyau]
sysfs_kf_write+0x3c [noyau]
kernfs_fop_write+0x125 [noyau]
__vfs_write+0x1b [noyau]
vfs_write+0xb8 [noyau]
sys_write+0x55 [noyau]
do_syscall_64+0x73 [noyau]
entry_SYSCALL_64_after_hwframe+0x3d [noyau]
__write_nocancel+0x7 [libc-2.23.so]
[inconnu]
3809631 3809631 systemd-udevd blk_freeze_queue
blk_freeze_queue+0x1 [noyau]
queue_requests_store+0xb6 [noyau]
queue_attr_store+0x5c [noyau]
sysfs_kf_write+0x3c [noyau]
kernfs_fop_write+0x125 [noyau]
__vfs_write+0x1b [noyau]
vfs_write+0xb8 [noyau]
sys_write+0x55 [noyau]
do_syscall_64+0x73 [noyau]
entry_SYSCALL_64_after_hwframe+0x3d [noyau]
__write_nocancel+0x7 [libc-2.23.so]
[inconnu]
Les rĂšgles Udev changent assez rarement et cela se fait gĂ©nĂ©ralement sous contrĂŽle. Nous constatons donc que mĂȘme l'application de valeurs dĂ©jĂ dĂ©finies entraĂźne une augmentation du dĂ©lai de transmission des requĂȘtes de l'application au disque. Bien sĂ»r, gĂ©nĂ©rer des Ă©vĂ©nements udev lorsqu'il n'y a pas de changements dans la configuration des disques (par exemple, un pĂ©riphĂ©rique n'est pas branchĂ©/dĂ©branchĂ©), n'est pas une bonne pratique. NĂ©anmoins, nous pouvons aider le noyau Ă ne pas effectuer de travail inutile et Ă ne pas « geler » la file des requĂȘtes si cela n'est pas nĂ©cessaire. corrigent la situation.
Conclusion
eBPF est un outil extrĂȘmement flexible et puissant. Dans cet article, nous avons examinĂ© un cas pratique et dĂ©montrĂ© une petite partie de ce qu'il est possible de faire. Si vous ĂȘtes intĂ©ressĂ© par le dĂ©veloppement d'outils BCC, il vaut la peine de consulter , qui dĂ©crit bien les bases du fonctionnement.
Il existe Ă©galement d'autres outils intĂ©ressants pour le dĂ©bogage et le profilage basĂ©s sur eBPF. L'un d'eux est , qui permet d'Ă©crire des lignes de code puissantes et de petits programmes dans un langage de type awk. L'autre est , qui permet de collecter des mĂ©triques bas-niveau Ă haute rĂ©solution directement sur votre serveur Prometheus, avec la possibilitĂ© d'obtenir par la suite une belle visualisation et mĂȘme des alertes.
Source : habr.com
