От висока латентност на Ceph до Kernel Patch с помощта на eBPF/BCC

В Linux има много инструменти за отстраняване на проблеми с ядрото и приложенията. Повечето от тях оказват негативно влияние върху производителността на приложенията и не могат да се използват в продукция.

Преди няколко години беше разработен още един инструмент — eBPF. Той дава възможност за проследяване на ядрото и потребителските приложения с ниски разходи и без необходимост от повторно компилиране на програмите и зареждане на външни модули в ядрото.

Вече съществуват множество полезни утилити, които използват eBPF, и в тази статия ще разгледаме как да напишем собствена утилита за профилиране, базирана на библиотеката PythonBCC. Статията е основана на реални събития. Ще преминем през процеса от появата на проблема до неговото разрешаване, за да покажем как могат да бъдат използвани съществуващите утилити в конкретни ситуации.

Ceph е бавен

В кластера Ceph добавиха нов хост. След миграцията на част от данните на него забелязахме, че скоростта на обработка на записните заявки е много по-ниска, отколкото на другите сървъри.

В отличие от другите платформи, на този хост се използваше bcache и ново ядро linux 4.15. Хост с такава конфигурация се използваше тук за първи път. И в този момент беше ясно, че причината за проблема теоретично можеше да бъде всичко.

Изследване на хоста

Нека започнем с това, да видим какво се случва вътре в процеса ceph-osd. За целта ще използваме perf и flamescope (повече информация може да се прочете тук):

Тази картина показва, че функцията fdatasync() е прекарала много време при изпращането на запитване в функцията generic_make_request(). Что значи, че най-вероятно, причината за проблемите е някъде извън самия демон osd. Това може да бъде или ядрото, или дисковете. Изходните данни от iostat показваха висока латентност на обработката на запитванията от bcache-дисковете.

При проверка на хоста открихме, че демонът systemd-udevd използва голямо количество CPU — около 20% на няколко ядра. Това е странно поведение, така че трябва да изясним причината за него. Тъй като Systemd-udevd работи с uevent-и, решихме да ги наблюдаваме чрез udevadm monitor. Оказва се, че се генерира голямо количество събития за промяна за всяко блочно устройство в системата. Това е доста необичайно, така че ще трябва да се проучи какво генерира всички тези събития.

Използване на BCC Toolkit

Както вече установихме, ядрото (и демонът ceph в системния повик) прекарва много време в generic_make_request(). Нека измерим скоростта на изпълнение на тази функция. В BCC уже има чудесен инструмент — funclatency. Ще следим демон по неговия PID с интервал между отчетите от 1 секунда и ще извеждаме резултата в милисекунди.

Обикновено тази функция работи бързо. Всичко, което прави — е да предаде заявката в опашката на устройството.

Bcache е сложен механизъм, който на практика се състои от три диска:

• backing device (кеширащ диск), в този случай това е бавен HDD;
• caching device (кеширащ диск), тук това е един дял от NVMe устройството;
• виртуалното устройство bcache, с което работи приложението.

Знаем, че предаването на заявката забавя, но за кое от тези устройства? Ще разгледаме това малко по-късно.

Сега знаем, че uevent-ите вероятно създават проблеми. Да разберем какво точно предизвиква тяхната генерация не е толкова лесно. Нека предположим, че е софтуер, който се стартира периодично. Нека видим какъв софтуер се изпълнява в системата, с помощта на скрипта execsnoop от същия набор от утилити BCC. Ще го стартираме и ще насочим извода към файл.

Например така:

/usr/share/bcc/tools/execsnoop  | tee ./execdump

Няма да представяме пълния Изход на execsnoop, но една интересуваща ни редица изглеждаше така:

sh 1764905 5802 0 sudo arcconf getconfig 1 AD | grep Temperature | awk -F '[:\/]' '{print $2}' | sed 's\/^ ([0-9]*) C.*\/1\/'

Третата колона е PPID (родителски PID) на процеса. Процесът с PID 5802 се оказа един от потоковете на нашата система за мониторинг. При проверка на конфигурацията на системата за мониторинг бяха открити грешно зададени параметри. Температурата на HBA адаптера се отчита на всеки 30 секунди, което е много по-често, отколкото е необходимо. След промяна на интервала на проверката на по-дълъг, открихме, че забавянето на обработката на заявките на този хост вече не личи на фона на другите хостове.

Но все още не е ясно защо bcache устройството се забавяше толкова много. Подготвихме тестова платформа с идентична конфигурация и опитахме да възпроизведем проблема, стартирайки fio на bcache, периодично изпълнявайки udevadm trigger за генериране на uevents.

Писане на инструменти, основани на BCC

Нека се опитаме да напишем прост инструмент за проследяване и извеждане на екрана на най-бавните заявки generic_make_request(). Интересува ни и името на диска, за който е извикана тази функция.

Планът е прост:

• Регистрираме kprobe на generic_make_request():
  • Съхраняваме в паметта името на диска, достъпно чрез аргумента на функцията;
  • Съхраняваме времевата марка.

• Регистрираме kretprobe при връщане от generic_make_request():
  • Получаваме текущата времева марка;
  • Търсим запазената времева марка и я сравняваме с текущата;
  • Ако резултатът е по-голям от зададения, намираме запазеното име на диска и го извеждаме на терминала.

Kprobes и kretprobes използват механизма на точките за спиране, за да променят кода на функциите в движение. Можете да прочетете документацията и добра статия по тази тема. Ако погледнем кода на различните утилити в BCC, можем да забележим, че те имат идентична структура. Така че в тази статия ще пропуснем парсинга на аргументите на скрипта и ще преминем направо към самата BPF програма.

Текстът на eBPF в python-скрипта изглежда по следния начин:

bpf_text = “”” # Тук ще бъде кодът на bpf програмата “””

За обмен на данни между функциите, eBPF програмите използват хеш-таблица. Така ще постъпим и ние. Като ключ ще използваме PID на процеса, а като стойност ще определим структурата:

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);

Тук регистрираме хеш-таблица, наречена p, с ключ от тип u64 и стойност от тип struct data_t. Таблицата ще бъде достъпна в контекста на нашата BPF програма. Макросът BPF_PERF_OUTPUT регистрира друга таблица, наречена events, която се използва за передача на данни в потребителското пространство.

При измерване на закъсненията между извикване на функция и връщане от нея, или между извиквания на различни функции, е нужно да се има предвид, че получените данни трябва да принадлежат на един и същи контекст. С други думи, трябва да помним за възможното паралелно изпълнение на функциите. Имаме възможност да измерим закъснението между извикването на функция в контекста на един процес и връщането от тази функция в контекста на друг процес, но това вероятно ще е безполезно. Добър пример тук може да бъде утилитата biolatency, където като ключ на хеш-таблицата се задава указател на struct request, която отразява една заявка към диска.

След това трябва да напишем код, който ще се изпълнява при извикване на изследваната функция:

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);
}

Тук вторият аргумент ще бъде заменен с първия аргумент на извиканата функция. generic_make_request(). След това получаваме PID на процеса, в контекста на който работим, и текуща времева отметка в наносекунди. Записваме всичко това в новосъздаденото struct data_t data. Името на диска получаваме от структурата bio, която се предава при извикването на generic_make_request(), и го запазваме в същата структура data. Последната стъпка е да добавим запис в хеш-таблицата, за която стана дума по-рано.

Следващата функция ще бъде извикана при връщането от 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);
    }
}

Тази функция е подобна на предишната: установяваме PID на процеса и времевата отметка, но не заделяме памет за нова структура данни. Вместо това търсим в хеш-таблицата вече съществуващата структура според ключа == текущия PID. Ако структурата бъде намерена, установяваме името на стартирания процес и го добавяме в нея.

Бидарният сдвиг, който използваме тук, е необходим, за да получим GID на нишката, т.е. PID на основния процес, който е стартирал нишката, в контекста на който работим. Извикваната от нас функция bpf_get_current_pid_tgid() връща както GID на нишката, така и нейния PID в едно 64-битово значение.

При извеждането в терминала в момента не ни интересува нишката, а основният процес. След сравнението на получената задержка с зададения праг, предаваме нашата структура data в пространството на потребителя чрез таблицата events, след което изтриваме записа от p.

В python-скрипта, който ще зарежда този код, трябва да заменим MIN_US и FACTOR с праговете на забавяне и единиците време, които ще предадем чрез аргументите:

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"

Сега трябва да подготвим BPF програмата чрез макрос BPF и да регистрираме пробите:

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")

Също така ще трябва да определим struct data_t в нашия скрипт, в противен случай нищо няма да може да се прочете:

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)]

Последната стъпка — извеждане на данните на терминала:

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)
# форматиране на изхода
start = 0
while 1:
    try:
        b.perf_buffer_poll()
    except KeyboardInterrupt:
        exit()

Самият скрипт е достъпен на GItHub. Нека опитаме да го стартираме на тестова платформа, където работи fio, записваща на bcache, и да извикаме udevadm monitor:

Най-накрая! Сега виждаме, че това, което изглеждаше като забавящо bcache устройство, всъщност е забавяща функция generic_make_request() за кеширания диск.

Разгледайте ядро

Какво точно забавя при предаване на заявката? Виждаме, че закъснението се появява дори преди началото на отчитането на заявката, т.е. отчетът на конкретната заявка за по-нататъшно извеждане на статистиката по нея (/ proc/diskstats или iostat) все още не е започнал. Това лесно може да се провери, като пуснете iostat по време на възпроизвеждане на проблема, или BCC скрипт biolatency, който се основава на началото и края на отчитането на заявките. Нито една от тези утилити няма да покаже проблеми за заявките към кеширания диск.

Ако погледнем функциите generic_make_request(), ще видим, че преди започването на отчитането на заявката се извикват още две функции. Първата — generic_make_request_checks(), извършва проверки на легитимността на заявката относно настройките на диска. Втората — blk_queue_enter(), в която има интересен повик 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));

В него ядрото чака размразяването на опашката. Измерваме закъснението 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    	|                                    	|

Изглежда, че сме близо до разгадаването. Функциите, използвани за "замразяване/размразяване" на опашката — това са blk_mq_freeze_queue и blk_mq_unfreeze_queue. Те се използват, когато е необходимо да се променят настройките на опашката на заявките, потенциално опасни за заявките, които се намират в тази опашка. При извикването на blk_mq_freeze_queue() от функцията blk_freeze_queue_start() се инкрементира броячът q->mq_freeze_depth. След това ядрото изчаква изпразването на опашката в blk_mq_freeze_queue_wait().

Времето на чакане за почистване на тази опашка е равно на забавянето на диска, тъй като ядрото изчаква завършването на всички поставени в опашката операции. Премахването на опашката, промените в настройките ще бъдат приложени. След това ще бъде извикан blk_mq_unfreeze_queue(), намаляваща брояча freeze_depth.

Сега знаем достатъчно, за да поправим ситуацията. Командата udevadm trigger води до прилагане на настройките за блочно устройство. Тези настройки са описани в правилата на udev. Можем да разберем, кои точно настройки „замразяват“ опашката, опитвайки се да ги променим чрез sysfs или като прегледаме изходния код на ядрото. Освен това можем да пробваме инструмента BCC trace, който ще изведе в терминала трасета на стека на ядрото и потребителското пространство за всеки повик blk_freeze_queue, например:

~# /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]

Правилата на Udev променят доста рядко и обикновено се случват под контрол. Така виждаме, че дори прилагането на вече зададени стойности предизвиква прилив на забавяне на предаването на заявката от приложението към диска. Разбира се, генерирането на събития udev, когато няма никакви промени в конфигурацията на дисковете (например, устройството не се свързва/отключва), не е много добра практика. Въпреки това, можем да помогнем на ядрото да не извършва ненужна работа и да не „замразява“ опашката на заявките, ако в това няма никаква необходимост. Три малки комита поправят ситуацията.

Заключение

eBPF е изключително гъвкав и мощен инструмент. В статията разгледахме един практически случай и демонстрирахме малка част от това, което е възможно да се направи. Ако се интересувате от разработването на BCC инструменти, си струва да погледнете официалния туториал, който добре описва основите на работата.

Има и други интересни инструменти за отстраняване на грешки и профилиране, базирани на eBPF. Един от тях е bpftrace, който позволява написването на мощни едноредови скриптове и малки програми на awk-подобен език. Другият е ebpf_exporter, който позволява събиране на нискоуровневи метрики с висока резолюция директно във вашия prometheus сървър, с възможност по-късно да получите красива визуализация и дори аларми.

Източник: habr.com