Од висока латентност на Ceph до закрпа на кернелот користејќи eBPF/BCC

Linux има голем број алатки за дебагирање на кернелот и апликациите. Повеќето од нив имаат негативно влијание врз перформансите на апликацијата и не можат да се користат во производството.

Пред неколку години имаше развиена е друга алатка - eBPF. Овозможува следење на кернелот и корисничките апликации со ниски трошоци и без потреба да се обновуваат програми и да се вчитуваат модули од трети страни во кернелот.

Веќе има многу алатки за апликации кои користат eBPF, а во оваа статија ќе погледнеме како да напишете сопствена алатка за профилирање врз основа на библиотеката PythonBCC. Статијата е заснована на вистински настани. Ќе одиме од проблем до поправка за да покажеме како постоечките комунални услуги може да се користат во конкретни ситуации.

Цеф е бавен

Нов домаќин е додаден во кластерот Ceph. По мигрирањето на некои од податоците во него, забележавме дека брзината на обработка на барањата за пишување од него беше многу помала отколку на другите сервери.

За разлика од другите платформи, овој домаќин користеше bcache и новиот Linux 4.15 кернел. Ова беше прв пат домаќин на оваа конфигурација да се користи овде. И во тој момент беше јасно дека коренот на проблемот теоретски може да биде што било.

Истражување на домаќинот

Да почнеме со гледање на она што се случува во процесот на ceph-osd. За ова ќе користиме перф и пламенскоп (повеќе за кои можете да прочитате тука):

Сликата ни кажува дека функцијата fdatasync () потроши многу време испраќајќи барање до функциите generic_make_request(). Ова значи дека најверојатно причината за проблемите е некаде надвор од самиот osd daemon. Ова може да биде или кернелот или дисковите. Излезот на iostat покажа висока латентност во обработката на барањата од дисковите за bcache.

При проверка на домаќинот, откривме дека демонот systemd-udevd троши голема количина на време на процесорот - околу 20% на неколку јадра. Ова е чудно однесување, па треба да откриете зошто. Бидејќи Systemd-udevd работи со uevents, решивме да ги погледнеме во целост udevadm монитор. Излегува дека се генерирани голем број настани за промени за секој блок уред во системот. Ова е сосема невообичаено, па ќе треба да погледнеме што ги генерира сите овие настани.

Користење на приборот со алатки за BCC

Како што веќе дознавме, кернелот (и цеф демонот во системскиот повик) поминува многу време во generic_make_request(). Ајде да се обидеме да ја измериме брзината на оваа функција. ВО БКК Веќе постои прекрасна алатка - функционалност. Ќе го следиме демонот според неговиот 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():
  • Го добиваме тековниот временски печат;
  • Го бараме зачуваниот временски печат и го споредуваме со тековниот;
  • Ако резултатот е поголем од наведениот, тогаш го наоѓаме зачуваното име на дискот и го прикажуваме на терминалот.

Ксонди и kretprobes користете механизам за точка на прекин за да го промените кодот на функцијата во лет. Можете да читате документација и добро статија на оваа тема. Ако го погледнете кодот на различни комунални услуги во БКК, тогаш може да се види дека имаат идентична структура. Така, во оваа статија ќе го прескокнеме парсирањето на аргументите на скриптата и ќе преминеме на самата програма BPF.

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

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 монитор:

Конечно! Сега гледаме дека она што изгледаше како застој во 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_замрзнување_длабочина. После ова, кернелот чека да се испразни редицата blk_mq_freeze_queue_wait().

Времето потребно за да се исчисти оваа редица е еквивалентно на латентноста на дискот бидејќи кернелот чека да се завршат сите операции во редот. Откако ќе се испразни редицата, се применуваат промените на поставките. По што се нарекува blk_mq_unfreeze_queue(), намалувајќи го бројачот замрзнување_длабочина.

Сега знаеме доволно за да ја поправиме ситуацијата. Командата за активирање 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 кога нема промени во конфигурацијата на дискот (на пример, уредот не е монтиран/исклучен) не е добра практика. Сепак, можеме да му помогнеме на кернелот да не прави непотребна работа и да го замрзне редот за барање ако тоа не е потребно. Три мали посветат поправете ја ситуацијата.

Заклучок

eBPF е многу флексибилна и моќна алатка. Во написот разгледавме еден практичен случај и демонстриравме мал дел од тоа што може да се направи. Ако сте заинтересирани за развој на BCC комунални услуги, вреди да се погледне официјален туторијал, кој добро ги опишува основите.

Постојат и други интересни алатки за дебагирање и профилирање базирани на eBPF. Еден од нив - bpftrace, кој ви овозможува да пишувате моќни еднократни линии и мали програми на јазик сличен на awk. Друго - ebpf_exporter, ви овозможува да собирате метрика на ниско ниво и со висока резолуција директно во вашиот сервер Prometheus, со можност подоцна да добивате убави визуелизации, па дури и предупредувања.

Извор: www.habr.com