От High Ceph Latency до Kernel Patch с помощта на eBPF/BCC

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

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

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

Цеф е бавен

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

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

Разследване на домакина

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

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

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

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

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

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

Bcache е сложно устройство, което всъщност се състои от три диска:

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

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

Сега знаем, че е вероятно събитията да причинят проблеми. Да се ​​установи какво точно причинява тяхното генериране не е толкова лесно. Да приемем, че това е някакъв софтуер, който се стартира периодично. Нека да видим какъв вид софтуер работи в системата с помощта на скрипт 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 тригер за генериране на uevents.

Писане на инструменти, базирани на BCC

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

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

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

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

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

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

bpf_text = “”” # Here will be the bpf program code “””

За обмен на данни между функциите програмите 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 регистрира друга таблица, извикана събития, който се използва за предаване на данни в потребителското пространство.

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

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

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

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

Когато извеждаме към терминала, в момента не се интересуваме от нишката, но се интересуваме от главния процес. След сравняване на полученото забавяне с даден праг, ние предаваме нашата структура данни в потребителското пространство чрез таблица събития, след което изтриваме записа от 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)
# format output
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 скрипт, което се основава на началото и края на отчитането на заявката. Нито една от тези помощни програми няма да покаже проблеми за заявки към кеширания диск.

Ако разгледаме функцията 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 предизвиква прилагането на настройките за блоковото устройство. Тези настройки са описани в правилата на udev. Можем да открием кои настройки замразяват опашката, като се опитаме да ги променим чрез sysfs или като погледнем изходния код на ядрото. Можем също да опитаме помощната програма BCC проследи, който ще изведе следи на стека на ядрото и потребителското пространство за всяко повикване към терминала 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, с възможност по-късно да получавате красиви визуализации и дори предупреждения.

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