Linux memiliki banyak alat dan aplikasi debugging kernel. Sebagian besar dari mereka mempengaruhi kinerja aplikasi dan tidak dapat digunakan dalam produksi.
Beberapa tahun yang lalu,
alat lain dikembangkan - eBPF. Itu memungkinkan untuk melacak aplikasi kernel dan pengguna dengan overhead rendah dan tanpa perlu membangun kembali program dan memuat modul pihak ketiga ke dalam kernel.
Sudah ada banyak utilitas aplikasi yang menggunakan eBPF, dan dalam artikel ini kita akan melihat bagaimana menulis utilitas profil kita sendiri berdasarkan pada pustaka
PythonBCC . Artikel ini didasarkan pada peristiwa nyata. Kami akan beralih dari tampilan masalah ke koreksi untuk menunjukkan bagaimana utilitas yang ada dapat digunakan dalam situasi tertentu.
Ceph lambat
Host baru telah ditambahkan ke cluster Ceph. Setelah memigrasi beberapa data ke dalamnya, kami perhatikan bahwa kecepatan pemrosesan permintaan penulisan jauh lebih rendah daripada di server lain.
Tidak seperti platform lain, bcache dan kernel linux 4.15 baru digunakan pada host ini. Sejumlah konfigurasi ini digunakan di sini untuk pertama kalinya. Dan pada saat itu jelas bahwa secara teoritis apa pun bisa menjadi akar masalah.
Investigasi tuan rumah
Untuk memulainya, mari kita lihat apa yang terjadi di dalam proses ceph-osd. Untuk melakukan ini, kami menggunakan
perf dan
flamescope (lebih lanjut tentang yang dapat dibaca di
sini ):
Gambar memberi tahu kita bahwa fungsi
fdatasync () menghabiskan banyak waktu mengirim permintaan ke fungsi
generic_make_request () . Ini berarti bahwa kemungkinan besar penyebab masalahnya adalah di suatu tempat di luar osd daemon itu sendiri. Itu bisa berupa kernel atau disk. Output iostat menunjukkan latensi tinggi dalam memproses permintaan dengan bcache disk.
Ketika memeriksa host, kami menemukan bahwa daemon systemd-udevd menghabiskan banyak waktu CPU - sekitar 20% pada banyak core. Ini adalah perilaku yang aneh, jadi Anda perlu mencari tahu penyebabnya. Karena Systemd-udevd bekerja dengan banyak, kami memutuskan untuk melihatnya melalui
monitor udevadm . Ternyata sejumlah besar peristiwa perubahan dihasilkan untuk setiap perangkat blok dalam sistem. Ini sangat tidak biasa, jadi Anda perlu melihat apa yang menghasilkan semua peristiwa ini.
Menggunakan BCC Toolkit
Seperti yang sudah kita ketahui, kernel (dan daemon ceph di system call) menghabiskan banyak waktu di
generic_make_request () . Mari kita coba mengukur kecepatan fungsi ini.
BCC sudah memiliki utilitas yang hebat -
funclatency . Kami akan melacak daemon dengan PID-nya dengan interval antara output informasi 1 detik dan output hasilnya dalam milidetik.
Biasanya fungsi ini cepat. Yang dia lakukan hanyalah mengirim permintaan ke antrian driver perangkat.
Bcache adalah perangkat kompleks yang sebenarnya terdiri dari tiga disk:
- perangkat pendukung (disk yang di-cache), dalam hal ini HDD yang lambat;
- perangkat caching (caching disk), ini dia salah satu bagian dari perangkat NVMe;
- perangkat virtual bcache yang digunakan aplikasi.
Kita tahu bahwa pengiriman permintaan lambat, tetapi untuk perangkat yang mana? Kami akan mengatasinya nanti.
Kita sekarang tahu bahwa banyak kemungkinan penyebab masalah. Menemukan apa yang sebenarnya menyebabkan generasi mereka tidak sesederhana itu. Misalkan ini adalah semacam perangkat lunak yang berjalan secara berkala. Mari kita lihat
jenis perangkat lunak apa yang diluncurkan pada sistem menggunakan skrip
execsnoop dari
rangkaian utilitas BCC yang sama. Jalankan dan arahkan output ke file.
Misalnya, seperti ini:
/usr/share/bcc/tools/execsnoop | tee ./execdump
Kami tidak akan memberikan hasil lengkap dari execsnoop di sini, tetapi satu baris yang menarik bagi kami tampak seperti ini:
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 (induk PID) dari proses. Proses dengan PID 5802 ternyata menjadi salah satu utas sistem pemantauan kami. Saat memeriksa konfigurasi sistem pemantauan, ditemukan parameter yang salah. Suhu adaptor HBA diambil sekali setiap 30 detik, yang jauh lebih sering daripada yang diperlukan. Setelah mengubah interval verifikasi menjadi yang lebih lama, kami menemukan bahwa keterlambatan dalam memproses permintaan pada host ini tidak lagi menonjol dari host lainnya.
Tetapi masih belum jelas mengapa perangkat bcache sangat lambat. Kami menyiapkan platform pengujian dengan konfigurasi yang identik dan mencoba mereproduksi masalah dengan menjalankan fio on bcache, secara berkala memulai pemicu udevadm untuk menghasilkan uevents.
Menulis Alat Berbasis BCC
Mari kita coba menulis utilitas sederhana untuk melacak dan menampilkan panggilan paling lambat ke
generic_make_request () . Kami juga tertarik dengan nama drive tempat fungsi ini dipanggil.
Rencananya sederhana:
- Daftarkan kprobe ke generic_make_request () :
- Kami menyimpan nama disk yang dapat diakses melalui argumen fungsi;
- Simpan cap waktu.
- Daftarkan kretprobe untuk kembali dari generic_make_request () :
- Dapatkan cap waktu saat ini;
- Kami mencari stempel waktu yang disimpan dan membandingkannya dengan yang sekarang;
- Jika hasilnya lebih besar dari yang ditentukan, maka kami menemukan nama disk yang disimpan dan menampilkannya di terminal.
Kprobes dan
kretprobes menggunakan mekanisme breakpoint untuk mengubah kode fungsi dengan cepat. Anda dapat membaca
dokumentasi dan artikel yang
bagus tentang topik ini. Jika Anda melihat kode berbagai utilitas di
BCC , Anda akan melihat bahwa mereka memiliki struktur yang sama. Jadi dalam artikel ini kita akan menghilangkan parsing argumen skrip dan beralih ke program BPF itu sendiri.
Teks eBPF di dalam skrip python terlihat seperti ini:
bpf_text = “””
Untuk bertukar data antar fungsi, program eBPF menggunakan
tabel hash . Begitu juga kita. Sebagai kuncinya, kita akan menggunakan PID dari proses, dan sebagai nilai kita mendefinisikan struktur:
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 tabel hash yang disebut
p , dengan kunci tipe
u64 dan nilai tipe
struct data_t . Tabel akan tersedia dalam konteks program BPF kami. Makro BPF_PERF_OUTPUT mendaftarkan tabel lain yang disebut
peristiwa , yang digunakan untuk
mentransfer data ke ruang pengguna.
Ketika mengukur penundaan antara panggilan fungsi dan kembali dari panggilan fungsi, atau di antara panggilan ke fungsi yang berbeda, harus diingat bahwa data yang diterima harus berasal dari konteks yang sama. Dengan kata lain, Anda perlu mengingat tentang kemungkinan peluncuran fungsi secara paralel. Kami memiliki kesempatan untuk mengukur penundaan antara memanggil fungsi dalam konteks satu proses dan kembali dari fungsi itu dalam konteks proses lain, tetapi ini kemungkinan besar tidak berguna. Contoh yang baik di sini adalah
utilitas biolatency , di mana pointer ke
permintaan struct , yang mencerminkan
permintaan disk tunggal, ditetapkan sebagai kunci dalam tabel hash.
Selanjutnya, kita perlu menulis kode yang akan dijalankan ketika fungsi yang diselidiki 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, argumen kedua dari fungsi
generic_make_request () disebut akan diganti sebagai argumen kedua. Setelah itu, kami mendapatkan PID dari proses di mana kami bekerja, dan cap waktu saat ini dalam nanodetik. Kami menulis semua ini di
data data_t struct yang baru dialokasikan . Kami mendapatkan nama disk dari struktur
bio , yang diteruskan saat memanggil
generic_make_request () , dan menyimpannya dalam struktur
data yang sama. Langkah terakhir adalah menambahkan entri ke tabel hash yang disebutkan sebelumnya.
Fungsi berikut akan dipanggil 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 mirip dengan yang sebelumnya: kami mengenali proses PID dan timestamp, tetapi tidak mengalokasikan memori untuk struktur data baru. Sebagai gantinya, kita melihat tabel hash untuk struktur yang ada dengan kunci == PID saat ini. Jika struktur ditemukan, maka kita akan mengetahui nama proses yang sedang berjalan dan menambahkannya.
Pergeseran biner yang kami gunakan di sini diperlukan untuk mendapatkan GID utas. yaitu PID dari proses utama yang memulai utas dalam konteks yang sedang kami kerjakan. Fungsi
bpf_get_current_pid_tgid () yang kita
panggil mengembalikan GID dari utas dan PID-nya dalam satu nilai 64-bit.
Saat keluaran ke terminal, sekarang kami tidak tertarik pada aliran, tetapi pada proses utama. Setelah membandingkan keterlambatan yang diterima dengan ambang yang diberikan, kami mentransfer struktur
data kami ke ruang pengguna melalui tabel
acara , dan kemudian menghapus catatan dari
hal .
Dalam skrip python yang akan memuat kode ini, kita perlu mengganti MIN_US dan FACTOR dengan ambang keterlambatan dan satuan waktu, yang akan kita bahas melalui argumen:
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 menyiapkan program BPF melalui
makro BPF dan mendaftarkan 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")
Kami juga harus mendefinisikan
struct data_t dalam skrip kami, jika tidak, kami tidak akan dapat membaca apa pun:
TASK_COMM_LEN = 16
Langkah terakhir adalah output 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)
Skrip itu sendiri tersedia di
GItHub . Mari kita coba jalankan di platform uji di mana fio ditulis dalam bcache dan panggil monitor udevadm:
Akhirnya! Sekarang kita melihat bahwa apa yang tampak seperti perangkat pengereman bcache sebenarnya adalah panggilan pengereman ke
generic_make_request () pada drive yang di-cache.
Gali ke dalam kernel
Apa yang sebenarnya melambat selama pengiriman permintaan? Kami melihat bahwa keterlambatan terjadi bahkan sebelum dimulainya penghitungan permintaan, yaitu memperhitungkan permintaan khusus untuk statistik lebih lanjut tentang itu (/ proc / diskstats atau iostat) belum dimulai. Ini dapat dengan mudah diverifikasi dengan menjalankan iostat saat mereproduksi masalah, atau
skrip biolatensi BCC , yang didasarkan pada awal dan akhir dari akuntansi permintaan. Tak satu pun dari utilitas ini akan menunjukkan masalah untuk permintaan ke drive yang di-cache.
Jika kita melihat fungsi
generic_make_request () , kita akan melihat bahwa dua fungsi lagi dipanggil sebelum permintaan
direkam . Yang pertama,
generic_make_request_checks () , memeriksa keabsahan permintaan untuk pengaturan disk. Yang kedua adalah
blk_queue_enter () , yang memiliki panggilan menarik ke
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 dalamnya, kernel menunggu pencairan antrian. Kami mengukur keterlambatan
blk_queue_enter () :
~
Tampaknya kita sudah dekat dengan solusi. Fungsi yang digunakan untuk "membekukan / mencairkan" antrian adalah
blk_mq_freeze_queue dan
blk_mq_unfreeze_queue . Mereka digunakan ketika perlu untuk mengubah pengaturan antrian permintaan, yang berpotensi berbahaya untuk permintaan dalam antrian ini. Ketika
blk_mq_freeze_queue () dipanggil, fungsi
blk_freeze_queue_start () menambah
q-> mq_freeze_depth counter . Setelah itu, kernel menunggu pengosongan antrian di
blk_mq_freeze_queue_wait () .
Waktu tunggu untuk menghapus antrian ini sama dengan latensi disk, karena kernel menunggu semua operasi yang antri untuk menyelesaikan. Segera setelah antrian kosong, perubahan pada pengaturan diterapkan. Kemudian
blk_mq_unfreeze_queue () dipanggil, mengurangi counter
freeze_depth .
Sekarang kita cukup tahu untuk memperbaiki situasi. Perintah memicu udevadm menghasilkan aplikasi pengaturan untuk perangkat blok. Pengaturan ini dijelaskan dalam aturan udev. Kita dapat mengetahui pengaturan mana yang “membekukan” antrian dengan mencoba mengubahnya melalui sysfs atau dengan melihat kode sumber kernel. Kita juga dapat mencoba utilitas
jejak BCC, yang menampilkan tumpukan kernel dan jejak ruang pengguna untuk terminal untuk setiap panggilan
blk_freeze_queue , misalnya:
~
Aturan Udev jarang berubah dan biasanya ini terjadi di bawah kendali. Jadi kita melihat bahwa bahkan penggunaan nilai yang sudah ditetapkan menyebabkan lonjakan keterlambatan dalam mengirimkan permintaan dari aplikasi ke disk. Tentu saja, untuk menghasilkan peristiwa udev ketika tidak ada perubahan dalam konfigurasi disk (misalnya, perangkat tidak terhubung / terputus) bukan praktik yang baik. Namun, kami dapat membantu kernel tidak bekerja sia-sia dan tidak membekukan antrian permintaan jika ini tidak diperlukan.
Tiga komit kecil memperbaiki situasi.
Kesimpulan
eBPF adalah alat yang sangat fleksibel dan kuat. Dalam artikel tersebut, kami memeriksa satu kasus praktis dan menunjukkan sebagian kecil dari apa yang mungkin dilakukan. Jika Anda tertarik untuk mengembangkan utilitas BCC, Anda harus melihat pada
tutorial resmi , yang menjelaskan dasar-dasarnya dengan baik.
Ada alat debugging dan profiling menarik lainnya berdasarkan eBPF. Salah satunya adalah
bpftrace , yang memungkinkan Anda untuk menulis program baris tunggal dan kecil yang kuat dalam bahasa mirip bahasa awk. Lain -
ebpf_exporter , memungkinkan Anda untuk mengumpulkan metrik resolusi tinggi tingkat rendah langsung ke server prometheus Anda, dengan kemampuan untuk mendapatkan visualisasi yang indah dan bahkan peringatan di masa depan.