Linux mempunyai sejumlah besar alat untuk menyahpepijat kernel dan aplikasi. Kebanyakannya mempunyai kesan negatif terhadap prestasi aplikasi dan tidak boleh digunakan dalam pengeluaran.
Beberapa tahun lalu ada - eBPF. Ia membolehkan untuk mengesan kernel dan aplikasi pengguna dengan overhed yang rendah dan tanpa perlu membina semula program dan memuatkan modul pihak ketiga ke dalam kernel.
Sudah terdapat banyak utiliti aplikasi yang menggunakan eBPF, dan dalam artikel ini kita akan melihat cara menulis utiliti profil anda sendiri berdasarkan perpustakaan . Artikel adalah berdasarkan peristiwa sebenar. Kami akan beralih daripada masalah kepada penyelesaian untuk menunjukkan cara utiliti sedia ada boleh digunakan dalam situasi tertentu.
Ceph Lambat
Hos baharu telah ditambahkan pada kluster Ceph. Selepas memindahkan beberapa data kepadanya, kami mendapati bahawa kelajuan memproses permintaan tulis olehnya adalah jauh lebih rendah daripada pada pelayan lain.
Tidak seperti platform lain, hos ini menggunakan bcache dan kernel linux 4.15 baharu. Ini adalah kali pertama hos konfigurasi ini digunakan di sini. Dan pada masa itu adalah jelas bahawa punca masalah secara teorinya boleh menjadi apa sahaja.
Menyiasat Tuan Rumah
Mari kita mulakan dengan melihat apa yang berlaku dalam proses ceph-osd. Untuk ini kami akan gunakan ΠΈ (lebih lanjut mengenai yang boleh anda baca ):
Gambar memberitahu kita bahawa fungsi fdatasync() menghabiskan banyak masa menghantar permintaan ke fungsi generic_make_request(). Ini bermakna kemungkinan besar punca masalah adalah di luar daemon osd itu sendiri. Ini boleh sama ada kernel atau cakera. Output iostat menunjukkan kependaman yang tinggi dalam memproses permintaan oleh cakera bcache.
Apabila menyemak hos, kami mendapati bahawa daemon systemd-udevd menggunakan sejumlah besar masa CPU - kira-kira 20% pada beberapa teras. Ini adalah tingkah laku yang pelik, jadi anda perlu mengetahui sebabnya. Memandangkan Systemd-udevd berfungsi dengan uevents, kami memutuskan untuk melihatnya monitor udevadm. Ternyata sebilangan besar peristiwa perubahan telah dihasilkan untuk setiap peranti blok dalam sistem. Ini agak luar biasa, jadi kita perlu melihat apa yang menjana semua peristiwa ini.
Menggunakan BCC Toolkit
Seperti yang telah kita ketahui, kernel (dan daemon ceph dalam panggilan sistem) menghabiskan banyak masa dalam generic_make_request(). Mari cuba mengukur kelajuan fungsi ini. DALAM Sudah ada utiliti yang hebat - kefungsian. Kami akan mengesan daemon dengan PIDnya dengan selang 1 saat antara output dan output hasil dalam milisaat.
Ciri ini biasanya berfungsi dengan cepat. Apa yang dilakukannya ialah menghantar permintaan kepada baris gilir pemacu peranti.
Bcache ialah peranti kompleks yang sebenarnya terdiri daripada tiga cakera:
- peranti sokongan (cakera cache), dalam kes ini ia adalah HDD yang perlahan;
- peranti caching (cakera caching), ini adalah satu partition peranti NVMe;
- peranti maya bcache yang mana aplikasi berjalan.
Kami tahu bahawa penghantaran permintaan adalah perlahan, tetapi untuk peranti ini yang manakah? Kami akan berurusan dengan ini sedikit kemudian.
Kini kita tahu bahawa uevents berkemungkinan menyebabkan masalah. Mencari apa sebenarnya yang menyebabkan generasi mereka tidak begitu mudah. Mari kita anggap bahawa ini adalah sejenis perisian yang dilancarkan secara berkala. Mari lihat jenis perisian yang berjalan pada sistem menggunakan skrip execsnoop daripada yang sama . Mari jalankan dan hantar output ke fail.
Contohnya seperti ini:
/usr/share/bcc/tools/execsnoop | tee ./execdump
Kami tidak akan menunjukkan output penuh execsnoop di sini, tetapi satu baris yang menarik kepada kami kelihatan seperti ini:
sh 1764905 5802 0 sudo arcconf getconfig 1 AD | grep Temperature | awk -F '[:/]' '{print $2}' | sed 's/^ ([0-9]*) C.*/1/'
Lajur ketiga ialah PPID (induk PID) proses. Proses dengan PID 5802 ternyata menjadi salah satu rangkaian sistem pemantauan kami. Apabila menyemak konfigurasi sistem pemantauan, parameter yang salah ditemui. Suhu penyesuai HBA diambil setiap 30 saat, yang lebih kerap daripada yang diperlukan. Selepas menukar selang semakan kepada yang lebih lama, kami mendapati bahawa kependaman pemprosesan permintaan pada hos ini tidak lagi menonjol berbanding hos lain.
Tetapi masih tidak jelas mengapa peranti bcache begitu perlahan. Kami menyediakan platform ujian dengan konfigurasi yang sama dan cuba menghasilkan semula masalah dengan menjalankan fio pada bcache, secara berkala menjalankan pencetus udevadm untuk menjana uevents.
Menulis Alat Berasaskan BCC
Mari cuba tulis utiliti mudah untuk mengesan dan memaparkan panggilan paling perlahan generic_make_request(). Kami juga berminat dengan nama pemacu yang mana fungsi ini dipanggil.
Pelannya mudah:
- Daftar kprobe pada generic_make_request():
- Kami menyimpan nama cakera ke dalam memori, boleh diakses melalui hujah fungsi;
- Kami menyimpan cap masa.
- Daftar kretprobe untuk pulang dari generic_make_request():
- Kami mendapat cap masa semasa;
- Kami mencari cap masa yang disimpan dan membandingkannya dengan yang semasa;
- Jika hasilnya lebih besar daripada yang ditentukan, maka kami mencari nama cakera yang disimpan dan memaparkannya pada terminal.
Kprobes ΠΈ kretprobes gunakan mekanisme titik putus untuk menukar kod fungsi dengan cepat. Anda boleh membaca ΠΈ artikel mengenai topik ini. Jika anda melihat kod pelbagai utiliti dalam , maka anda boleh melihat bahawa mereka mempunyai struktur yang sama. Jadi dalam artikel ini kita akan melangkau hujah skrip menghuraikan dan beralih ke program BPF itu sendiri.
Teks eBPF di dalam skrip python kelihatan seperti ini:
bpf_text = βββ # Here will be the bpf program code βββ
Untuk menukar data antara fungsi, program eBPF menggunakan . Kami akan melakukan perkara yang sama. Kami akan menggunakan proses PID sebagai kunci, dan menentukan struktur sebagai nilai:
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);
Di sini kami mendaftarkan jadual hash yang dipanggil p, dengan jenis kunci u64 dan nilai jenis struct data_t. Jadual akan tersedia dalam konteks program BPF kami. Makro BPF_PERF_OUTPUT mendaftarkan jadual lain yang dipanggil acara, yang digunakan untuk ke dalam ruang pengguna.
Apabila mengukur kelewatan antara memanggil fungsi dan kembali daripadanya, atau antara panggilan ke fungsi yang berbeza, anda perlu mengambil kira bahawa data yang diterima mestilah tergolong dalam konteks yang sama. Dengan kata lain, anda perlu ingat tentang kemungkinan pelancaran fungsi selari. Kami mempunyai keupayaan untuk mengukur kependaman antara memanggil fungsi dalam konteks satu proses dan kembali daripada fungsi itu dalam konteks proses lain, tetapi ini mungkin tidak berguna. Contoh yang baik di sini ialah , di mana kunci jadual cincang ditetapkan kepada penuding ke permintaan struct, yang mencerminkan satu permintaan cakera.
Seterusnya, kita perlu menulis kod yang akan dijalankan apabila fungsi yang sedang dikaji dipanggil:
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);
}
Di sini hujah pertama fungsi yang dipanggil akan digantikan sebagai hujah kedua . Selepas ini, kami mendapat PID proses dalam konteks yang kami kerjakan, dan cap masa semasa dalam nanosaat. Kami menulis semuanya dalam yang baru dipilih struct data_t data. Kami mendapat nama cakera daripada struktur bio, yang diluluskan apabila memanggil generic_make_request(), dan simpan dalam struktur yang sama data. Langkah terakhir ialah menambah entri pada jadual hash yang telah dinyatakan sebelum ini.
Fungsi berikut akan dipanggil semasa kembali dari 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);
}
}
Fungsi ini serupa dengan yang sebelumnya: kami mengetahui PID proses dan cap waktu, tetapi tidak memperuntukkan memori untuk struktur data baharu. Sebaliknya, kami mencari jadual hash untuk struktur sedia ada menggunakan kekunci == PID semasa. Jika struktur ditemui, maka kami mengetahui nama proses yang sedang berjalan dan menambahnya.
Anjakan binari yang kami gunakan di sini diperlukan untuk mendapatkan GID benang. mereka. PID proses utama yang memulakan utas dalam konteks yang kami sedang kerjakan. Fungsi yang kita panggil mengembalikan kedua-dua GID benang dan PIDnya dalam satu nilai 64-bit.
Apabila mengeluarkan ke terminal, kami tidak berminat dengan benang, tetapi kami berminat dengan proses utama. Selepas membandingkan kelewatan yang terhasil dengan ambang yang diberikan, kami melepasi struktur kami data ke dalam ruang pengguna melalui jadual acara, selepas itu kami memadamkan entri daripada p.
Dalam skrip python yang akan memuatkan kod ini, kita perlu menggantikan MIN_US dan FACTOR dengan ambang kelewatan dan unit masa, yang akan kita lalui dengan hujah:
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"
Sekarang kita perlu menyediakan program BPF melalui dan daftar sampel:
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")
Kita juga perlu tentukan struct data_t dalam skrip kami, jika tidak, kami tidak akan dapat membaca apa-apa:
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)]
Langkah terakhir ialah mengeluarkan data ke 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()
Skrip itu sendiri boleh didapati di . Mari cuba jalankannya pada platform ujian di mana fio sedang berjalan, menulis ke bcache, dan memanggil monitor udevadm:
Akhirnya! Sekarang kita melihat bahawa apa yang kelihatan seperti peranti bcache yang terhenti sebenarnya adalah panggilan yang terhenti generic_make_request() untuk cakera cache.
Gali ke dalam Kernel
Apakah sebenarnya yang perlahan semasa penghantaran permintaan? Kami melihat bahawa kelewatan berlaku walaupun sebelum permulaan perakaunan permintaan, i.e. perakaunan permintaan khusus untuk keluaran statistik lanjut mengenainya (/proc/diskstats atau iostat) belum bermula. Ini boleh disahkan dengan mudah dengan menjalankan iostat semasa menghasilkan semula masalah, atau , yang berdasarkan permulaan dan akhir perakaunan permintaan. Tiada satu pun daripada utiliti ini akan menunjukkan masalah untuk permintaan kepada cakera cache.
Jika kita lihat fungsinya generic_make_request(), maka kita akan melihat bahawa sebelum permintaan memulakan perakaunan, dua lagi fungsi dipanggil. pertama - generic_make_request_checks(), melakukan semakan pada kesahihan permintaan berkenaan tetapan cakera. Kedua - , yang mempunyai cabaran yang menarik :
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));
Di dalamnya, kernel menunggu giliran untuk dinyahbeku. Mari kita ukur kelewatan 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 | |
Nampaknya kita hampir kepada penyelesaian. Fungsi yang digunakan untuk membekukan/mennyahbeku baris gilir ialah ΠΈ . Ia digunakan apabila perlu untuk menukar tetapan baris gilir permintaan, yang berpotensi berbahaya untuk permintaan dalam baris gilir ini. Apabila memanggil blk_mq_freeze_queue() fungsi kaunter bertambah q->mq_freeze_depth. Selepas ini, kernel menunggu sehingga baris gilir dikosongkan .
Masa yang diperlukan untuk mengosongkan baris gilir ini adalah bersamaan dengan kependaman cakera kerana kernel menunggu semua operasi baris gilir selesai. Setelah baris gilir kosong, perubahan tetapan digunakan. Selepas itu ia dipanggil , mengurangkan kaunter freeze_depth.
Sekarang kita cukup tahu untuk membetulkan keadaan. Perintah pencetus udevadm menyebabkan tetapan untuk peranti blok digunakan. Tetapan ini diterangkan dalam peraturan udev. Kita boleh mencari tetapan mana yang membekukan baris gilir dengan cuba mengubahnya melalui sysfs atau dengan melihat kod sumber kernel. Kami juga boleh mencuba utiliti BCC , yang akan mengeluarkan surih tindanan kernel dan ruang pengguna untuk setiap panggilan ke terminal blk_freeze_queue, sebagai contoh:
~# /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]
Peraturan Udev jarang berubah dan biasanya ini berlaku secara terkawal. Oleh itu, kita melihat bahawa walaupun menggunakan nilai yang telah ditetapkan menyebabkan lonjakan dalam kelewatan dalam memindahkan permintaan daripada aplikasi ke cakera. Sudah tentu, menjana peristiwa udev apabila tiada perubahan dalam konfigurasi cakera (contohnya, peranti tidak dipasang/diputuskan sambungan) bukanlah amalan yang baik. Walau bagaimanapun, kami boleh membantu kernel tidak melakukan kerja yang tidak perlu dan membekukan baris gilir permintaan jika tidak perlu. betulkan keadaan.
Kesimpulan
eBPF ialah alat yang sangat fleksibel dan berkuasa. Dalam artikel itu kami melihat satu kes praktikal dan menunjukkan sebahagian kecil daripada perkara yang boleh dilakukan. Jika anda berminat untuk membangunkan utiliti BCC, anda patut melihatnya , yang menerangkan asas dengan baik.
Terdapat alat penyahpepijatan dan pemprofilan lain yang menarik berdasarkan eBPF. Salah seorang daripada mereka - , yang membolehkan anda menulis satu baris yang berkuasa dan program kecil dalam bahasa seperti awk. Satu lagi - , membolehkan anda mengumpul metrik tahap rendah, resolusi tinggi terus ke pelayan prometheus anda, dengan keupayaan untuk kemudian mendapatkan visualisasi yang cantik dan juga makluman.
Sumber: www.habr.com