Ang Linux ay may malaking bilang ng mga tool para sa pag-debug ng kernel at mga application. Karamihan sa mga ito ay may negatibong epekto sa pagganap ng aplikasyon at hindi magagamit sa produksyon.
Isang pares ng mga taon na ang nakalipas ay nagkaroon - eBPF. Ginagawa nitong posible na masubaybayan ang kernel at mga application ng user na may mababang overhead at nang hindi na kailangang muling buuin ang mga programa at i-load ang mga third-party na module sa kernel.
Marami nang application utilities na gumagamit ng eBPF, at sa artikulong ito titingnan natin kung paano isulat ang iyong sariling profileing utility batay sa library . Ang artikulo ay batay sa mga totoong pangyayari. Aayusin natin ang problema para ipakita kung paano magagamit ang mga kasalukuyang utility sa mga partikular na sitwasyon.
Mabagal si Ceph
Isang bagong host ang naidagdag sa Ceph cluster. Pagkatapos i-migrate ang ilan sa data dito, napansin namin na ang bilis ng pagproseso ng mga kahilingan sa pagsulat nito ay mas mababa kaysa sa iba pang mga server.
Hindi tulad ng ibang mga platform, ang host na ito ay gumamit ng bcache at ang bagong linux 4.15 kernel. Ito ang unang pagkakataon na ginamit dito ang isang host ng configuration na ito. At sa sandaling iyon ay malinaw na ang ugat ng problema ay maaaring theoretically maging anuman.
Iniimbestigahan ang Host
Magsimula tayo sa pamamagitan ng pagtingin sa kung ano ang nangyayari sa loob ng proseso ng ceph-osd. Para dito gagamitin namin ΠΈ (higit pa tungkol sa kung saan maaari mong basahin ):
Ang larawan ay nagsasabi sa amin na ang function fdatasync() gumugol ng maraming oras sa pagpapadala ng kahilingan sa mga function generic_make_request(). Nangangahulugan ito na malamang na ang sanhi ng mga problema ay nasa labas ng osd daemon mismo. Ito ay maaaring alinman sa kernel o mga disk. Ang output ng iostat ay nagpakita ng mataas na latency sa pagproseso ng mga kahilingan sa pamamagitan ng mga bcache disk.
Kapag sinusuri ang host, nalaman namin na ang systemd-udevd daemon ay kumokonsumo ng malaking halaga ng oras ng CPU - mga 20% sa ilang mga core. Ito ay kakaibang pag-uugali, kaya kailangan mong malaman kung bakit. Dahil gumagana ang Systemd-udevd sa mga uevent, nagpasya kaming tingnan ang mga ito udevadm monitor. Lumalabas na isang malaking bilang ng mga kaganapan sa pagbabago ang nabuo para sa bawat block device sa system. Ito ay medyo hindi pangkaraniwan, kaya kailangan nating tingnan kung ano ang bumubuo sa lahat ng mga kaganapang ito.
Gamit ang BCC Toolkit
Tulad ng nalaman na natin, ang kernel (at ang ceph daemon sa system call) ay gumugugol ng maraming oras sa generic_make_request(). Subukan nating sukatin ang bilis ng function na ito. SA Mayroon nang isang kahanga-hangang utility - pagpapaandar. Susubaybayan namin ang daemon sa pamamagitan ng PID nito na may 1 segundong pagitan sa pagitan ng mga output at output ang resulta sa millisecond.
Ang tampok na ito ay karaniwang gumagana nang mabilis. Ang ginagawa lang nito ay ipasa ang kahilingan sa queue ng driver ng device.
Bcache ay isang kumplikadong aparato na talagang binubuo ng tatlong mga disk:
- backing device (cached disk), sa kasong ito ito ay isang mabagal na HDD;
- caching device (caching disk), narito ang isang partition ng NVMe device;
- ang bcache virtual device kung saan tumatakbo ang application.
Alam namin na mabagal ang paghahatid ng kahilingan, ngunit para sa alin sa mga device na ito? Haharapin natin ito mamaya.
Alam na natin ngayon na ang mga uevent ay malamang na magdulot ng mga problema. Ang paghahanap kung ano ang eksaktong sanhi ng kanilang henerasyon ay hindi napakadali. Ipagpalagay natin na ito ay isang uri ng software na pana-panahong inilulunsad. Tingnan natin kung anong uri ng software ang tumatakbo sa system gamit ang isang script execsnoop mula sa pareho . Patakbuhin natin ito at ipadala ang output sa isang file.
Halimbawa tulad nito:
/usr/share/bcc/tools/execsnoop | tee ./execdump
Hindi namin ipapakita ang buong output ng execsnoop dito, ngunit ang isang linya ng interes sa amin ay ganito ang hitsura:
sh 1764905 5802 0 sudo arcconf getconfig 1 AD | grep Temperature | awk -F '[:/]' '{print $2}' | sed 's/^ ([0-9]*) C.*/1/'
Ang ikatlong column ay ang PPID (parent PID) ng proseso. Ang proseso sa PID 5802 ay naging isa sa mga thread ng aming monitoring system. Kapag sinusuri ang pagsasaayos ng sistema ng pagsubaybay, natagpuan ang mga maling parameter. Kinukuha ang temperatura ng HBA adapter tuwing 30 segundo, na mas madalas kaysa sa kinakailangan. Matapos baguhin ang agwat ng pagsusuri sa mas mahaba, nalaman namin na ang latency sa pagproseso ng kahilingan sa host na ito ay hindi na namumukod-tangi kumpara sa ibang mga host.
Ngunit hindi pa rin malinaw kung bakit napakabagal ng bcache device. Naghanda kami ng platform ng pagsubok na may magkaparehong configuration at sinubukang kopyahin ang problema sa pamamagitan ng pagpapatakbo ng fio sa bcache, pana-panahong pagpapatakbo ng udevadm trigger upang makabuo ng mga uevents.
Pagsusulat ng BCC-Based Tools
Subukan nating magsulat ng isang simpleng utility upang masubaybayan at ipakita ang pinakamabagal na mga tawag generic_make_request(). Interesado din kami sa pangalan ng drive kung saan tinawag ang function na ito.
Ang plano ay simple:
- Magrehistro kprobe sa generic_make_request():
- I-save namin ang pangalan ng disk sa memorya, naa-access sa pamamagitan ng argumento ng function;
- Ise-save namin ang timestamp.
- Magrehistro kretprobe para sa pagbabalik mula sa generic_make_request():
- Nakukuha namin ang kasalukuyang timestamp;
- Hinahanap namin ang naka-save na timestamp at inihambing ito sa kasalukuyan;
- Kung ang resulta ay mas malaki kaysa sa tinukoy, pagkatapos ay makikita namin ang naka-save na pangalan ng disk at ipakita ito sa terminal.
Kprobes ΠΈ kretprobes gumamit ng mekanismo ng breakpoint upang baguhin ang function code sa mabilisang. Mababasa mo ΠΈ artikulo sa paksang ito. Kung titingnan mo ang code ng iba't ibang mga utility sa , pagkatapos ay makikita mo na mayroon silang magkaparehong istraktura. Kaya sa artikulong ito ay laktawan natin ang pag-parse ng mga argumento ng script at magpapatuloy sa mismong programa ng BPF.
Ang teksto ng eBPF sa loob ng script ng python ay ganito:
bpf_text = βββ # Here will be the bpf program code βββ
Para makipagpalitan ng data sa pagitan ng mga function, ginagamit ng mga eBPF program . Ganun din ang gagawin natin. Gagamitin namin ang proseso ng PID bilang susi, at tutukuyin ang istraktura bilang ang halaga:
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);
Dito nagrerehistro kami ng hash table na tinatawag p, na may uri ng key u64 at isang halaga ng uri struct data_t. Ang talahanayan ay magiging available sa konteksto ng aming BPF program. Ang BPF_PERF_OUTPUT macro ay nagrerehistro ng isa pang table na tinatawag mga kaganapan, na ginagamit para sa sa espasyo ng gumagamit.
Kapag sinusukat ang mga pagkaantala sa pagitan ng pagtawag sa isang function at pagbabalik mula dito, o sa pagitan ng mga tawag sa iba't ibang mga function, kailangan mong isaalang-alang na ang natanggap na data ay dapat kabilang sa parehong konteksto. Sa madaling salita, kailangan mong tandaan ang tungkol sa posibleng parallel launch ng mga function. May kakayahan kaming sukatin ang latency sa pagitan ng pagtawag sa isang function sa konteksto ng isang proseso at pagbabalik mula sa function na iyon sa konteksto ng isa pang proseso, ngunit malamang na walang silbi ito. Isang magandang halimbawa dito , kung saan nakatakda ang hash table key sa isang pointer sa kahilingan sa istruktura, na sumasalamin sa isang kahilingan sa disk.
Susunod, kailangan nating isulat ang code na tatakbo kapag tinawag ang function sa ilalim ng pag-aaral:
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);
}
Dito ang unang argumento ng tinatawag na function ay papalitan bilang pangalawang argumento . Pagkatapos nito, nakukuha namin ang PID ng proseso sa konteksto kung saan kami nagtatrabaho, at ang kasalukuyang timestamp sa nanosecond. Isinulat namin ang lahat ng ito sa isang bagong napili struct data_t data. Nakukuha namin ang pangalan ng disk mula sa istraktura bio, na ipinapasa kapag tumatawag generic_make_request(), at i-save ito sa parehong istraktura data. Ang huling hakbang ay magdagdag ng entry sa hash table na nabanggit kanina.
Ang sumusunod na function ay tatawagin sa pagbabalik mula sa 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);
}
}
Ang function na ito ay katulad ng nauna: nalaman namin ang PID ng proseso at ang timestamp, ngunit hindi naglalaan ng memorya para sa bagong istraktura ng data. Sa halip, hinahanap namin ang hash table para sa isang umiiral nang istraktura gamit ang key == kasalukuyang PID. Kung natagpuan ang istraktura, malalaman namin ang pangalan ng proseso ng pagpapatakbo at idagdag ito dito.
Ang binary shift na ginagamit namin dito ay kailangan para makuha ang thread GID. mga. PID ng pangunahing proseso na nagsimula sa thread sa konteksto kung saan kami nagtatrabaho. Ang function na tinatawag namin ibinabalik ang parehong GID ng thread at ang PID nito sa isang solong 64-bit na halaga.
Kapag nag-output sa terminal, hindi kami kasalukuyang interesado sa thread, ngunit interesado kami sa pangunahing proseso. Pagkatapos ihambing ang nagresultang pagkaantala sa isang ibinigay na threshold, ipinapasa namin ang aming istraktura data sa espasyo ng gumagamit sa pamamagitan ng talahanayan mga kaganapan, pagkatapos ay tinanggal namin ang entry mula sa p.
Sa script ng python na maglo-load ng code na ito, kailangan nating palitan ang MIN_US at FACTOR ng mga threshold ng pagkaantala at mga yunit ng oras, na ipapasa natin sa mga argumento:
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"
Ngayon ay kailangan nating ihanda ang BPF program sa pamamagitan ng at magrehistro ng mga sample:
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")
Kailangan din nating tukuyin struct data_t sa aming script, kung hindi, wala kaming mababasa:
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)]
Ang huling hakbang ay ang mag-output ng data sa 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()
Ang script mismo ay magagamit sa . Subukan nating patakbuhin ito sa isang test platform kung saan tumatakbo ang fio, sumusulat sa bcache, at tumawag sa udevadm monitor:
Sa wakas! Ngayon nakita namin na ang mukhang stalling bcache device ay talagang stalling call generic_make_request() para sa isang naka-cache na disk.
Maghukay sa Kernel
Ano nga ba ang bumabagal sa panahon ng paghahatid ng kahilingan? Nakikita namin na ang pagkaantala ay nangyayari bago pa man magsimula ang kahilingan sa accounting, i.e. hindi pa nagsisimula ang accounting ng isang partikular na kahilingan para sa karagdagang output ng mga istatistika dito (/proc/diskstats o iostat). Madali itong ma-verify sa pamamagitan ng pagpapatakbo ng iostat habang ginagawa ang problema, o , na batay sa simula at pagtatapos ng kahilingan sa accounting. Wala sa mga utility na ito ang magpapakita ng mga problema para sa mga kahilingan sa naka-cache na disk.
Kung titingnan natin ang function generic_make_request(), pagkatapos ay makikita natin na bago magsimula sa accounting ang kahilingan, dalawa pang function ang tinatawag. Una - generic_make_request_checks(), nagsasagawa ng mga pagsusuri sa pagiging lehitimo ng kahilingan tungkol sa mga setting ng disk. Pangalawa - , na may isang kawili-wiling hamon :
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));
Sa loob nito, hinihintay ng kernel ang pag-unfreeze ng pila. Sukatin natin ang pagkaantala 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 | |
Mukhang malapit na tayo sa solusyon. Ang mga function na ginagamit upang i-freeze/i-unfreeze ang isang queue ay ΠΈ . Ginagamit ang mga ito kapag kinakailangan na baguhin ang mga setting ng queue ng kahilingan, na posibleng mapanganib para sa mga kahilingan sa queue na ito. Kapag tumatawag blk_mq_freeze_queue() pagpapaandar ang counter ay incremented q->mq_freeze_depth. Pagkatapos nito, hinihintay ng kernel na mawalan ng laman ang pila .
Ang oras na kinakailangan upang i-clear ang queue na ito ay katumbas ng disk latency habang hinihintay ng kernel na makumpleto ang lahat ng naka-queue na operasyon. Kapag walang laman ang pila, ilalapat ang mga pagbabago sa mga setting. Pagkatapos nito ay tinawag ito , binabawasan ang counter freeze_depth.
Ngayon sapat na ang alam natin para itama ang sitwasyon. Ang udevadm trigger command ay nagiging sanhi ng paglalapat ng mga setting para sa block device. Inilalarawan ang mga setting na ito sa mga panuntunan ng udev. Mahahanap natin kung aling mga setting ang nagpapalamig sa pila sa pamamagitan ng pagsubok na baguhin ang mga ito sa pamamagitan ng sysfs o sa pamamagitan ng pagtingin sa kernel source code. Maaari din nating subukan ang BCC utility , na maglalabas ng kernel at userspace stack traces para sa bawat tawag sa terminal blk_freeze_queue, halimbawa:
~# /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]
Ang mga panuntunan ng Udev ay medyo bihira at kadalasang nangyayari ito sa isang kinokontrol na paraan. Kaya't nakikita namin na kahit na ang paglalapat ng mga nakatakdang halaga ay nagdudulot ng pagtaas sa pagkaantala sa paglilipat ng kahilingan mula sa aplikasyon patungo sa disk. Siyempre, ang pagbuo ng mga kaganapan sa udev kapag walang mga pagbabago sa pagsasaayos ng disk (halimbawa, ang aparato ay hindi naka-mount/nadiskonekta) ay hindi isang magandang kasanayan. Gayunpaman, matutulungan namin ang kernel na huwag gumawa ng hindi kinakailangang trabaho at i-freeze ang queue ng kahilingan kung hindi ito kinakailangan. itama ang sitwasyon.
Konklusyon
Ang eBPF ay isang napaka-flexible at makapangyarihang tool. Sa artikulo ay tiningnan namin ang isang praktikal na kaso at ipinakita ang isang maliit na bahagi ng kung ano ang maaaring gawin. Kung interesado ka sa pagbuo ng mga kagamitan sa BCC, sulit na tingnan ito , na mahusay na naglalarawan sa mga pangunahing kaalaman.
May iba pang kawili-wiling mga tool sa pag-debug at pag-profile batay sa eBPF. Isa sa kanila - , na nagbibigay-daan sa iyong magsulat ng makapangyarihang mga one-liner at maliliit na programa sa mala-awk na wika. Isa pa - , ay nagbibigay-daan sa iyong mangolekta ng mababang antas, mataas na resolution ng mga sukatan nang direkta sa iyong prometheus server, na may kakayahang makakuha ng magagandang visualization at maging ng mga alerto sa ibang pagkakataon.
Pinagmulan: www.habr.com