Ada banyak alat untuk debugging kernel dan program userspace di Linux. Kebanyakan dari mereka memiliki dampak kinerja dan tidak dapat dengan mudah dijalankan di lingkungan produksi. Beberapa tahun yang lalu, eBPF
dikembangkan , yang menyediakan kemampuan untuk melacak kernel dan ruang pengguna dengan overhead rendah, tanpa perlu mengkompilasi ulang program atau memuat modul kernel.
Sekarang ada banyak alat yang menggunakan eBPF dan dalam artikel ini, kami akan menjelaskan cara menulis alat profil Anda sendiri menggunakan
pustaka PythonBCC . Artikel ini didasarkan pada masalah nyata dari lingkungan produksi. Kami akan memandu Anda menyelesaikan masalah dan menunjukkan bagaimana alat bcc yang ada dapat digunakan dalam beberapa kasus.
Ceph lambat
Platform baru ditambahkan ke ceph cluster. Setelah memigrasi beberapa data ke platform, latensi permintaan tulis lebih tinggi daripada di server lain.
Platform ini memiliki perangkat virtual caching baru - bcache, yang belum pernah kami gunakan di cluster ini sebelumnya - dan kernel baru - 4,15, yang masih tidak digunakan di tempat lain di cluster ini. Akar masalahnya bisa di mana saja, jadi mari kita lihat lebih dalam.
Investigasi tuan rumah
Mari kita lihat apa yang terjadi di dalam proses ceph-osd. Kami menggunakan alat tracing
perf dan
flamescope untuk membuat flamegraph:
Seperti yang dapat kita lihat dari flamegraph,
fdatasync () menghabiskan banyak waktu mengirimkan bio dalam fungsi
generic_make_request () . Jadi, akar masalah kita adalah di suatu tempat di luar daemon ceph. Mungkin masalah kernel, bcache, atau disk. Output iostat menunjukkan latensi tinggi untuk perangkat bcache.
Temuan mencurigakan lainnya adalah bahwa daemon systemd-udevd mengkonsumsi CPU; sekitar 20% pada banyak CPU. Ini perilaku aneh, jadi kita harus mencari tahu apa yang terjadi. Karena systemd-udevd bekerja dengan uevents, kita harus menggunakan
monitor udevadm untuk mengetahui apakah ada uevents di sistem. Setelah memeriksa, kami melihat bahwa banyak "perubahan" yang dihasilkan untuk setiap perangkat blok dalam sistem.
Ini tidak biasa, jadi kami akan mencari tahu apa yang menyebabkan semua ini dikirim.
Menggunakan BCC Toolkit
Seperti yang sudah kita ketahui, kernel (dan ceph daemon) menghabiskan banyak waktu untuk menjalankan fungsi
generic_make_requst () . Mari kita mengukur latensi menggunakan
funclatency dari
BCC toolkit , hanya untuk memastikan bahwa kita berada di jalur yang benar. Kami akan melacak PID daemon ceph (argumen -p) dalam interval 1 detik (-i) dan mencetak latensi dalam milidetik (-m).
Fungsi ini biasanya bekerja sangat cepat. Yang dilakukannya hanyalah mengirimkan struktur bio ke antrian driver perangkat.
Bcache adalah perangkat yang kompleks; sebenarnya, ini terdiri dari 3 perangkat: perangkat pendukung, yang merupakan HDD lambat dalam kasus kami; perangkat caching, yang merupakan partisi drive NVMe; dan perangkat virtual bcache, yang digunakan oleh aplikasi. Kami tahu pengiriman lambat, tetapi untuk perangkat apa? Ini adalah sesuatu yang akan kita lihat nanti.
Untuk saat ini, kita tahu bahwa uevents menyebabkan masalah pada daemon ceph dan kita harus menemukan perangkat lunak yang memicu uevents. Tidak mudah untuk menemukan apa yang menyebabkan uevents dihasilkan. Kami menganggap itu perangkat lunak yang hanya berjalan secara berkala. Untuk melihat apa yang sedang dieksekusi pada sistem, kami menggunakan
execsnoop dari BCC toolkit. Kita dapat menjalankannya dan mengarahkan
stdout ke file.
Sebagai contoh:
/usr/share/bcc/tools/execsnoop | tee ./execdump
Kami tidak akan memberikan output execsnoop penuh di sini, tetapi satu string menarik yang kami temukan di sana adalah:
sh 1764905 5802 0 sudo arcconf getconfig 1 AD | grep Temperature | awk -F '[:/]' '{print $2}' | sed 's/^ \([0-9]*\) C.*/\1/'
Kolom ketiga adalah PPID proses. Kami memeriksa apa itu 5802 dan melihat bahwa itu adalah salah satu utas daemon pemantauan kami. Melihat lebih jauh pada konfigurasi sistem pemantauan, kami menemukan parameter yang salah. Suhu HBA sedang diambil setiap 30 detik, yang terlalu sering. Setelah mengubah interval pemeriksaan ke nilai yang lebih tepat, kami melihat bahwa latensi kami cocok dengan platform lain.
Tetapi kita masih tidak tahu mengapa latensi bcache tinggi. Kami menyiapkan platform pengujian dengan konfigurasi yang sama dan mencoba mereproduksi masalah dengan fio pada perangkat bcache sementara secara bersamaan memicu udev dengan perintah memicu udevadm.
Menulis Alat Berbasis BCC
Apa yang akan kita lakukan di sini adalah menulis alat sederhana yang melacak panggilan generic_make_request () paling lambat dan mencetak nama disk yang dipanggil untuk fungsi tersebut.
Rencananya sederhana:
- Daftarkan kprobe di generic_make_request () :
- Simpan nama disk yang tersedia dari argumen fungsi
- Simpan cap waktu saat ini
- Daftarkan kretprobe di pernyataan pengembalian generic_make_request () :
- Ambil stempel waktu saat ini
- Cari stempel waktu yang disimpan sebelumnya dan bandingkan dengan yang sekarang
- Jika hasilnya lebih tinggi dari ambang, cari nama disk yang disimpan sebelumnya dan cetak ke terminal dengan informasi tambahan
Kprobes dan
kretprobes menggunakan breakpoint untuk mengubah kode fungsi saat runtime. Anda dapat menemukan
dokumentasi serta
artikel bagus tentang ini. Jika Anda melihat kode untuk
alat BCC yang berbeda, Anda akan melihat bahwa mereka semua memiliki struktur yang sama. Kami akan melewatkan argumen penguraian dan fokus pada program BPF itu sendiri.
Teks program kami akan didefinisikan dalam python sebagai berikut:
bpf_text = “””
Program BPF menggunakan
hashmaps untuk berbagi data antara berbagai fungsi. Kami akan menggunakan PID sebagai struktur kunci dan yang didefinisikan sendiri 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 kita mendaftarkan hashmap yang disebut
p dengan
tipe kunci
u64 dan tipe nilai
struct data_t . Peta ini dapat diakses dari konteks program BPF kami. Makro
BPF_PERF_OUTPUT mendaftarkan peta lain yang disebut
peristiwa , yang digunakan untuk
mendorong data ke ruang pengguna.
Saat mengukur latensi antara panggilan fungsi dan pengembaliannya atau antara satu panggilan fungsi dan yang lain, Anda harus yakin bahwa data yang Anda simpan dan akses nanti terkait dengan konteks yang sama. Dengan kata lain, Anda harus mengetahui eksekusi paralel lain dari fungsi yang sama. Dimungkinkan untuk melacak latensi antara pemanggilan fungsi dari satu proses dan pengembalian fungsi yang sama dari proses lain, tetapi ini tidak membantu kami. Contoh yang baik adalah
alat biolatensi di mana pointer ke
permintaan struct digunakan sebagai kunci hashmap.
Selanjutnya, kita harus menulis kode yang akan dieksekusi pada panggilan fungsi melalui mekanisme kprobe:
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 kita memiliki
argumen generic_make_request () pertama sebagai argumen kedua fungsi kita. Kemudian kita mendapatkan PID dan cap waktu saat ini dalam nanodetik dan menulisnya ke
data data_t struct yang baru dialokasikan. Kami mendapatkan nama disk dari struktur bio, yang diteruskan ke
generic_make_request () , dan menyimpannya ke
data kami. Langkah terakhir adalah menambahkan entri ke hashmap yang kami jelaskan sebelumnya.
Fungsi ini akan dieksekusi pada
generic_make_request () mengembalikan:
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); } }
Kami mendapatkan PID dan cap waktu dari output sebelumnya dan mencari peta hash untuk nilai di mana
kunci == PID saat ini . Jika ditemukan, kami mendapatkan nama proses yang sedang berjalan dan menambahkannya ke struktur
data . Apa yang kita lakukan dengan
data-> pid di sini memberi kita id grup utas. Fungsi
bpf_get_current_pid_tgid () yang sebelumnya disebut mengembalikan thread GID dan PID dari proses dalam nilai 64-bit yang sama.
Kami tidak tertarik pada setiap ID utas, tetapi kami ingin mengetahui PID utas utama. Setelah memeriksa bahwa latensi berada di atas ambang batas, kami mengirimkan struktur
data kami ke userspace melalui peta
peristiwa , lalu menghapus entri hashmap di bagian akhir.
Dalam skrip python kami, kami harus mengganti
MIN_US dan
FACTOR sesuai dengan ambang yang kami inginkan dan satuan waktu yang ingin kami lihat dalam hasil kami:
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"
Maka kita harus menyiapkan program BPF dengan
makro BPF () dan mendaftarkan probe:
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 mendefinisikan struktur yang sama dengan
struct data_t dalam skrip kami untuk membaca data dari program BPF:
TASK_COMM_LEN = 16
Langkah terakhir adalah mencetak data yang kita inginkan:
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)
Script lengkap tersedia di
GitHub . Mari kita jalankan skrip dan memicu peristiwa udev sementara fio menulis ke perangkat bcache:
Sukses! Sekarang kita melihat bahwa apa yang tampak seperti latensi tinggi untuk bcache adalah
generic_make_request () latensi untuk perangkat pendukungnya.
Gali ke dalam kernel
Apa yang diseret saat mengirimkan permintaan? Kita melihat bahwa lonjakan latensi terjadi sebelum permintaan akuntansi dimulai. Ini dapat dengan mudah diperiksa dengan menjalankan iostat selama masalah atau
skrip BCC biolatensi , yang didasarkan pada permulaan permintaan akuntansi, sehingga tidak ada alat yang akan menunjukkan masalah disk.
Jika kita melihat
generic_make_request () , kita melihat bahwa ada dua fungsi yang berjalan sebelum akuntansi dimulai. Yang pertama adalah
generic_make_request_checks () , yang ringan dan memeriksa bio sesuai dengan pengaturan perangkat, dll. Yang kedua adalah
blk_queue_enter () , yang memiliki panggilan
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));
Di sini kernel menunggu sampai antrian tidak beku. Mari kita mengukur latensi blk_queue_enter ():
~
Sepertinya kita sudah dekat. Fungsi yang digunakan untuk membekukan / mencairkan antrian adalah
blk_mq_freeze_queue dan
blk_mq_unfreeze_queue . Mereka digunakan untuk mengubah pengaturan antrian, yang dapat memengaruhi permintaan io yang saat ini dalam penerbangan. Ketika
blk_mq_freeze_queue () dipanggil,
q-> mq_freeze_depth ditambahkan di
blk_freeze_queue_start () . Setelah itu, kernel menunggu antrian menjadi kosong di
blk_mq_freeze_queue_wait () .
Waktu tunggu ini sama dengan latensi disk, karena kernel harus menunggu semua operasi io selesai. Ketika antrian kosong, perubahan dapat dilakukan. Langkah terakhir adalah memanggil
blk_mq_unfreeze_queue () , yang menurunkan penghitung
freeze_depth .
Sekarang kita cukup tahu untuk memperbaiki masalah ini. Perintah memicu udevadm mengubah pengaturan untuk perangkat blok. Pengaturan tersebut dijelaskan dalam aturan udev. Kita dapat mengetahui pengaturan apa yang membekukan antrian dengan mengubahnya melalui sysfs atau dengan melihat kode sumber kernel. Atau, kita dapat
memanggil jejak dari BCC toolkit untuk mencetak kernel dan tumpukan pengguna untuk setiap panggilan
blk_freeze_queue :
~
Aturan Udev tidak sering berubah, bahkan menetapkan nilai yang sudah ada ke parameter tertentu menyebabkan lonjakan pengiriman latensi untuk aplikasi. Tentu saja menghasilkan peristiwa udev ketika tidak ada perubahan dalam konfigurasi perangkat (tidak ada perangkat yang terpasang atau terlepas) bukanlah praktik yang baik. Namun, kita dapat mencegah kernel membekukan antrian jika tidak ada alasan untuk melakukan ini.
Tiga komitmen kecil memperbaiki masalah ini.
Kesimpulan
eBPF adalah instrumen yang sangat fleksibel dan kuat. Dalam artikel ini, kami hanya melihat satu kasus dan menunjukkan sedikit kemampuannya. Jika Anda tertarik untuk mengembangkan alat berbasis BCC, Anda harus melihat pada
tutorial resmi , yang menjelaskan konsep dasarnya.
Ada juga alat berbasis eBPF menarik lainnya yang tersedia untuk profil dan debugging. Salah satunya adalah
bpftrace , yang memungkinkan Anda menulis oneliner yang kuat dan program-program kecil dalam bahasa yang mirip bahasa awk. Yang lainnya adalah
ebpf_exporter , yang dapat mengumpulkan metrik resolusi tinggi tingkat rendah ke server prometheus Anda dengan visualisasi yang hebat dan kemampuan mengingatkan.