Линук има велики број алата за отклањање грешака у кернелу и апликацијама. Већина њих има негативан утицај на перформансе апликације и не може се користити у производњи.
Пре пар година било је - еБПФ. Омогућава праћење кернела и корисничких апликација са малим трошковима и без потребе за поновном изградњом програма и учитавањем модула независних произвођача у кернел.
Већ постоји много услужних програма који користе еБПФ, а у овом чланку ћемо погледати како да напишете сопствени услужни програм за профилисање на основу библиотеке . Чланак је заснован на стварним догађајима. Ићи ћемо од проблема до решења да бисмо показали како се постојећи услужни програми могу користити у одређеним ситуацијама.
Цепх је спор
Нови домаћин је додат у Цепх кластер. Након миграције неких података на њега, приметили смо да је брзина обраде захтева за писање од њега била много мања него на другим серверима.
За разлику од других платформи, овај домаћин је користио бцацхе и ново језгро Линук 4.15. Ово је био први пут да је домаћин ове конфигурације коришћен овде. И у том тренутку је било јасно да би корен проблема теоретски могао бити било шта.
Истражујући домаћина
Почнимо тако што ћемо погледати шта се дешава унутар цепх-осд процеса. За ово ћемо користити и (више о томе можете прочитати ):
Слика нам говори да је функција фдатасинц() провео доста времена слањем захтева функцијама генериц_маке_рекуест(). То значи да је највероватније узрок проблема негде изван самог осд демона. Ово може бити језгро или дискови. Иостат излаз је показао велико кашњење у обради захтева од стране бцацхе дискова.
Када смо проверавали хост, открили смо да демон системд-удевд троши велику количину ЦПУ времена - око 20% на неколико језгара. Ово је чудно понашање, па морате да сазнате зашто. Пошто Системд-удевд ради са догађајима, одлучили смо да их погледамо до краја удевадм монитор. Испоставило се да је генерисан велики број догађаја промене за сваки блок уређај у систему. Ово је прилично необично, па ћемо морати да погледамо шта генерише све ове догађаје.
Коришћење БЦЦ Тоолкит-а
Као што смо већ сазнали, кернел (и цепх демон у системском позиву) проводи доста времена у генериц_маке_рекуест(). Покушајмо да измеримо брзину ове функције. ИН Већ постоји дивна помоћ - фунцланци. Пратићемо демон помоћу његовог ПИД-а са интервалом од 1 секунде између излаза и исписати резултат у милисекундама.
Ова функција обично ради брзо. Све што ради је да проследи захтев у ред драјвера уређаја.
Бцацхе је сложен уређај који се заправо састоји од три диска:
- пратећи уређај (кеширани диск), у овом случају то је спор ХДД;
- кеш уређај (кеш диск), овде је ово једна партиција НВМе уређаја;
- бцацхе виртуелни уређај са којим се апликација покреће.
Знамо да је пренос захтева спор, али за који од ових уређаја? Позабавићемо се овим мало касније.
Сада знамо да ће догађаји вероватно изазвати проблеме. Пронаћи шта тачно узрокује њихову генерацију није тако лако. Претпоставимо да је ово нека врста софтвера који се периодично покреће. Хајде да видимо какав софтвер ради на систему помоћу скрипте екецснооп из истог . Хајде да га покренемо и пошаљемо излаз у датотеку.
На пример овако:
/usr/share/bcc/tools/execsnoop | tee ./execdump
Овде нећемо приказати комплетан излаз екецснооп-а, али једна линија која нас занима изгледала је овако:
sh 1764905 5802 0 sudo arcconf getconfig 1 AD | grep Temperature | awk -F '[:/]' '{print $2}' | sed 's/^ ([0-9]*) C.*/1/'
Трећа колона је ППИД (родитељски ПИД) процеса. Испоставило се да је процес са ПИД 5802 једна од нити нашег система за праћење. Приликом провере конфигурације система за праћење пронађени су погрешни параметри. Температура ХБА адаптера је мерена сваких 30 секунди, што је много чешће него што је потребно. Након промене интервала провере на дужи, открили смо да се кашњење обраде захтева на овом хосту више не истиче у поређењу са другим хостовима.
Али још увек није јасно зашто је бцацхе уређај био тако спор. Припремили смо тест платформу са идентичном конфигурацијом и покушали да репродукујемо проблем тако што смо покренули фио на бцацхе-у, повремено покретајући удевадм триггер за генерисање догађаја.
Писање алата заснованих на БЦЦ-у
Покушајмо да напишемо једноставан услужни програм за праћење и приказ најспоријих позива генериц_маке_рекуест(). Занима нас и назив драјва за који је ова функција позвана.
План је једноставан:
- Регистровати кпробе на генериц_маке_рекуест():
- Име диска чувамо у меморији, доступном преко аргумента функције;
- Чувамо временску ознаку.
- Регистровати кретпробе за повратак из генериц_маке_рекуест():
- Добијамо тренутну временску ознаку;
- Тражимо сачувану временску ознаку и упоређујемо је са тренутном;
- Ако је резултат већи од наведеног, проналазимо сачувано име диска и приказујемо га на терминалу.
Кпробес и кретпробес користите механизам тачке прекида за промену кода функције у ходу. Можете прочитати и чланак на ову тему. Ако погледате код разних услужних програма у , онда можете видети да имају идентичну структуру. Дакле, у овом чланку ћемо прескочити рашчлањивање аргумената скрипте и прећи на сам БПФ програм.
еБПФ текст унутар питхон скрипте изгледа овако:
bpf_text = “”” # Here will be the bpf program code “””
За размену података између функција, еБПФ програми користе . И ми ћемо учинити исто. Користићемо ПИД процеса као кључ, а структуру ћемо дефинисати као вредност:
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, са типом кључа уКСНУМКС и вредност типа струцт дата_т. Табела ће бити доступна у контексту нашег БПФ програма. Макро БПФ_ПЕРФ_ОУТПУТ региструје другу табелу која се зове догађаји, који се користи за у кориснички простор.
Када мерите кашњења између позива функције и враћања из ње, или између позива различитим функцијама, морате узети у обзир да примљени подаци морају припадати истом контексту. Другим речима, морате запамтити могуће паралелно покретање функција. Имамо могућност да измеримо кашњење између позива функције у контексту једног процеса и враћања из те функције у контексту другог процеса, али то је вероватно бескорисно. Добар пример би овде био , где је кључ хеш табеле постављен на показивач на струцт захтев, што одражава један захтев за диском.
Затим морамо да напишемо код који ће се покренути када се позове функција која се проучава:
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);
}
Овде ће први аргумент позване функције бити замењен као други аргумент . Након овога добијамо ПИД процеса у чијем контексту радимо и тренутну временску ознаку у наносекундама. Све то записујемо у свеже одабраном струцт дата_т дата. Име диска добијамо из структуре Био, који се преноси приликом позива генериц_маке_рекуест(), и сачувајте га у истој структури подаци. Последњи корак је додавање уноса у хеш табелу која је раније поменута.
Следећа функција ће бити позвана по повратку из генериц_маке_рекуест():
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);
}
}
Ова функција је слична претходној: сазнајемо ПИД процеса и временску ознаку, али не додељујемо меморију за нову структуру података. Уместо тога, тражимо у хеш табели већ постојећу структуру користећи кључ == тренутни ПИД. Ако је структура пронађена, онда сазнајемо име покренутог процеса и додајемо му га.
Бинарни помак који овде користимо је потребан да бисмо добили ГИД нити. оне. ПИД главног процеса који је покренуо нит у чијем контексту радимо. Функција коју зовемо враћа и ГИД нити и њен ПИД у једној 64-битној вредности.
Када излазимо на терминал, тренутно нас не занима нит, али нас занима главни процес. Након што упоредимо резултујуће кашњење са датим прагом, ми пролазимо нашу структуру подаци у кориснички простор преко табеле догађаји, након чега бришемо унос из p.
У питхон скрипти која ће учитати овај код, морамо да заменимо МИН_УС и ФАЦТОР праговима кашњења и временским јединицама, које ћемо проследити кроз аргументе:
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"
Сада треба да припремимо БПФ програм преко и регистровати узорке:
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")
Такође ћемо морати да утврдимо струцт дата_т у нашој скрипти, иначе нећемо моћи ништа да читамо:
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()
Сам сценарио је доступан на . Хајде да покушамо да га покренемо на тест платформи где фио ради, пише у бцацхе и позовемо удевадм монитор:
Коначно! Сада видимо да је оно што је изгледало као бцацхе уређај са одуговлачењем заправо позив који одуговлачи генериц_маке_рекуест() за кеширани диск.
Копајте у кернел
Шта се тачно успорава током преноса захтева? Видимо да до кашњења долази и пре почетка обрачуна захтева, тј. обрачун конкретног захтева за даљи излаз статистике о њему (/проц/дискстатс или иостат) још није почео. Ово се лако може проверити покретањем иостат-а док репродукујете проблем, или , који се заснива на почетку и крају обрачуна захтева. Ниједан од ових услужних програма неће показати проблеме за захтеве за кеширани диск.
Ако погледамо функцију генериц_маке_рекуест(), онда ћемо видети да се пре него што захтев започне обрачун, позивају још две функције. Први - генериц_маке_рекуест_цхецкс(), врши проверу легитимности захтева у вези са подешавањима диска. Друго - , који има занимљив изазов :
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));
У њему, кернел чека да се ред одмрзне. Хајде да измеримо кашњење блк_куеуе_ентер():
~# /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 | |
Изгледа да смо близу решења. Функције које се користе за замрзавање/одмрзавање реда су и . Користе се када је потребно променити поставке реда захтева, које су потенцијално опасне за захтеве у овом реду. Приликом позивања блк_мк_фреезе_куеуе() функцију бројач се повећава к->мк_фреезе_дептх. Након овога, кернел чека да се ред испразни .
Време које је потребно за брисање овог реда је еквивалентно кашњењу диска јер кернел чека да се све операције у реду доврше. Када је ред празан, промене подешавања се примењују. По чему се зове , смањење бројача фреезе_дептх.
Сада знамо довољно да исправимо ситуацију. Команда окидача удевадм изазива примену поставки за блок уређај. Ова подешавања су описана у удев правилима. Можемо да пронађемо која подешавања замрзавају ред тако што ћемо покушати да их променимо преко сисфс-а или гледањем у изворни код кернела. Такође можемо испробати услужни програм БЦЦ , који ће приказати трагове стека језгра и корисничког простора за сваки позив терминалу блк_фреезе_куеуе, на пример:
~# /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]
Удев правила се мењају прилично ретко и обично се то дешава на контролисан начин. Дакле, видимо да чак и примена већ постављених вредности изазива пораст кашњења у преносу захтева са апликације на диск. Наравно, генерисање удев догађаја када нема промена у конфигурацији диска (на пример, уређај није монтиран/искључен) није добра пракса. Међутим, можемо помоћи кернелу да не ради непотребан посао и да замрзне ред захтева ако то није неопходно. исправити ситуацију.
Zakljucak
еБПФ је веома флексибилан и моћан алат. У чланку смо погледали један практичан случај и показали мали део онога што се може учинити. Ако сте заинтересовани за развој БЦЦ услужних програма, вреди погледати , који добро описује основе.
Постоје и други занимљиви алати за отклањање грешака и профилисање засновани на еБПФ-у. Један од њих - , који вам омогућава да пишете моћне једноструке и мале програме на језику сличном авк-у. Други - , омогућава вам да прикупљате метрике ниског нивоа, високе резолуције директно на ваш прометхеус сервер, уз могућност да касније добијете прелепе визуелизације, па чак и упозорења.
Извор: ввв.хабр.цом