Linux memiliki banyak alat untuk men-debug kernel dan aplikasi. Kebanyakan dari mereka berdampak negatif pada kinerja aplikasi dan tidak dapat digunakan dalam produksi.
Beberapa tahun yang lalu ada - eBPF. Hal ini memungkinkan untuk melacak kernel dan aplikasi pengguna dengan overhead rendah dan tanpa perlu membangun kembali program dan memuat modul pihak ketiga ke dalam kernel.
Sudah banyak utilitas aplikasi yang menggunakan eBPF, dan dalam artikel ini kita akan melihat cara menulis utilitas profiling Anda sendiri berdasarkan perpustakaan . Artikel ini didasarkan pada peristiwa nyata. Kami akan membahas dari satu masalah ke perbaikan lainnya untuk menunjukkan bagaimana utilitas yang ada dapat digunakan dalam situasi tertentu.
Ceph Lambat
Host baru telah ditambahkan ke cluster Ceph. Setelah memigrasikan beberapa data ke server tersebut, kami melihat bahwa kecepatan pemrosesan permintaan tulis oleh server tersebut jauh lebih rendah dibandingkan server lain.
Tidak seperti platform lain, host ini menggunakan bcache dan kernel linux 4.15 yang baru. Ini adalah pertama kalinya sejumlah konfigurasi ini digunakan di sini. Dan pada saat itu jelas bahwa akar masalahnya secara teori bisa berupa apa saja.
Menyelidiki Tuan Rumah
Mari kita mulai dengan melihat apa yang terjadi di dalam proses ceph-osd. Untuk ini kami akan menggunakan ΠΈ (lebih lanjut tentang yang dapat Anda baca ):
Gambar tersebut memberitahu kita bahwa fungsinya sinkronisasi data() menghabiskan banyak waktu mengirimkan permintaan ke fungsi permintaan_pembuatan_generik(). Ini berarti kemungkinan besar penyebab masalah ada di luar daemon osd itu sendiri. Ini bisa berupa kernel atau disk. Output iostat menunjukkan latensi tinggi dalam memproses permintaan oleh disk bcache.
Saat memeriksa host, kami menemukan bahwa daemon systemd-udevd menghabiskan banyak waktu CPU - sekitar 20% pada beberapa inti. Ini adalah perilaku yang aneh, jadi Anda perlu mencari tahu alasannya. Karena Systemd-udevd bekerja dengan uevents, kami memutuskan untuk memeriksanya secara menyeluruh monitor udevadm. Ternyata sejumlah besar peristiwa perubahan dihasilkan untuk setiap perangkat blok di sistem. Ini sangat tidak biasa, jadi kita harus melihat apa yang menyebabkan semua kejadian ini.
Menggunakan Perangkat BCC
Seperti yang telah kita ketahui, kernel (dan daemon ceph dalam panggilan sistem) menghabiskan banyak waktu di permintaan_pembuatan_generik(). Mari kita coba mengukur kecepatan fungsi ini. DI DALAM Sudah ada utilitas luar biasa - fungsi. Kami akan melacak daemon berdasarkan PID-nya dengan interval 1 detik antara keluaran dan keluaran hasilnya dalam milidetik.
Fitur ini biasanya bekerja dengan cepat. Yang dilakukannya hanyalah meneruskan permintaan ke antrian driver perangkat.
cache adalah perangkat kompleks yang sebenarnya terdiri dari tiga disk:
- perangkat pendukung (cache disk), dalam hal ini adalah HDD yang lambat;
- perangkat caching (caching disk), ini adalah salah satu partisi perangkat NVMe;
- perangkat virtual bcache yang menjalankan aplikasi.
Kita tahu bahwa transmisi permintaan lambat, tetapi untuk perangkat manakah ini? Kita akan membahasnya nanti.
Kita sekarang tahu bahwa peristiwa mungkin akan menimbulkan masalah. Menemukan apa sebenarnya penyebab generasi mereka tidaklah mudah. Anggaplah ini adalah semacam perangkat lunak yang diluncurkan secara berkala. Mari kita lihat perangkat lunak apa yang berjalan pada sistem menggunakan skrip execnoop dari yang sama . Mari kita jalankan dan kirimkan hasilnya ke sebuah file.
Misalnya seperti ini:
/usr/share/bcc/tools/execsnoop | tee ./execdump
Kami tidak akan menampilkan keluaran lengkap dari execsnoop di sini, tetapi satu baris yang menarik bagi kami terlihat 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 (PID induk) dari proses. Proses dengan PID 5802 ternyata menjadi salah satu thread dari sistem monitoring kami. Saat memeriksa konfigurasi sistem pemantauan, ditemukan parameter yang salah. Suhu adaptor HBA diukur setiap 30 detik, lebih sering dari yang diperlukan. Setelah mengubah interval pemeriksaan menjadi lebih panjang, kami menemukan bahwa latensi pemrosesan permintaan pada host ini tidak lagi menonjol dibandingkan host lain.
Namun masih belum jelas mengapa perangkat bcache sangat lambat. Kami menyiapkan platform pengujian dengan konfigurasi yang sama dan mencoba mereproduksi masalah dengan menjalankan fio di bcache, menjalankan pemicu udevadm secara berkala untuk menghasilkan uevents.
Alat Penulisan Berbasis BCC
Mari kita coba menulis utilitas sederhana untuk melacak dan menampilkan panggilan paling lambat permintaan_pembuatan_generik(). Kami juga tertarik dengan nama drive yang digunakan untuk fungsi ini.
Rencananya sederhana:
- Daftar penyelidikan pada permintaan_pembuatan_generik():
- Kami menyimpan nama disk ke dalam memori, dapat diakses melalui argumen fungsi;
- Kami menyimpan stempel waktu.
- Daftar kretprobe untuk kembali dari permintaan_pembuatan_generik():
- Kami mendapatkan stempel waktu saat ini;
- Kami mencari stempel waktu yang disimpan dan membandingkannya dengan yang sekarang;
- Jika hasilnya lebih besar dari yang ditentukan, maka kami mencari nama disk yang disimpan dan menampilkannya di terminal.
Kprobe ΠΈ probe kret gunakan mekanisme breakpoint untuk mengubah kode fungsi dengan cepat. Kamu bisa membaca ΠΈ artikel tentang topik ini. Jika Anda melihat kode berbagai utilitas di , maka Anda dapat melihat bahwa mereka memiliki struktur yang identik. Jadi pada artikel ini kita akan melewatkan argumen parsing skrip dan beralih ke program BPF itu sendiri.
Teks eBPF di dalam skrip python terlihat seperti ini:
bpf_text = βββ # Here will be the bpf program code βββ
Untuk pertukaran data antar fungsi, program eBPF digunakan . Kami akan melakukan hal yang sama. Kami akan menggunakan proses PID sebagai kuncinya, dan mendefinisikan struktur sebagai nilainya:
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 tipe kunci u64 dan nilai tipe struct data_t. Tabel ini akan tersedia dalam konteks program BPF kami. Makro BPF_PERF_OUTPUT mendaftarkan tabel lain yang disebut peristiwa, yang digunakan untuk ke dalam ruang pengguna.
Saat mengukur penundaan antara pemanggilan suatu fungsi dan kembali dari fungsi tersebut, atau antara pemanggilan ke fungsi yang berbeda, Anda perlu memperhitungkan bahwa data yang diterima harus berasal dari konteks yang sama. Dengan kata lain, Anda perlu mengingat tentang kemungkinan peluncuran fungsi secara paralel. Kami memiliki kemampuan untuk mengukur latensi antara pemanggilan fungsi dalam konteks satu proses dan kembali dari fungsi tersebut dalam konteks proses lain, tetapi hal ini mungkin tidak berguna. Contoh yang bagus di sini adalah , di mana kunci tabel hash disetel ke penunjuk permintaan struktur, yang mencerminkan satu permintaan disk.
Selanjutnya, kita perlu menulis kode yang akan dijalankan ketika fungsi yang diteliti 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 pertama dari fungsi yang dipanggil akan diganti dengan argumen kedua . Setelah ini, kita mendapatkan PID dari proses dalam konteks yang sedang kita kerjakan, dan stempel waktu saat ini dalam nanodetik. Kami menuliskan semuanya di tempat yang baru dipilih struct data_t data. Kami mendapatkan nama disk dari strukturnya Bio, yang diteruskan saat menelepon permintaan_pembuatan_generik(), dan simpan dalam struktur yang sama data. Langkah terakhir adalah menambahkan entri ke tabel hash yang telah disebutkan sebelumnya.
Fungsi berikut akan dipanggil saat kembali dari permintaan_pembuatan_generik():
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: kita mengetahui PID proses dan stempel waktu, tetapi tidak mengalokasikan memori untuk struktur data baru. Sebagai gantinya, kami mencari tabel hash untuk struktur yang sudah ada menggunakan kunci == PID saat ini. Jika strukturnya ditemukan, maka kita cari tahu nama proses yang sedang berjalan dan tambahkan ke dalamnya.
Pergeseran biner yang kita gunakan di sini diperlukan untuk mendapatkan thread GID. itu. PID dari proses utama yang memulai thread dalam konteks yang sedang kita kerjakan. Fungsi yang kita panggil mengembalikan GID thread dan PID-nya dalam satu nilai 64-bit.
Saat mengeluarkan keluaran ke terminal, saat ini kami tidak tertarik pada utasnya, tetapi kami tertarik pada proses utama. Setelah membandingkan penundaan yang dihasilkan dengan ambang batas tertentu, kami meneruskan struktur kami data ke ruang pengguna melalui tabel peristiwa, setelah itu kami menghapus entri tersebut p.
Dalam skrip python yang akan memuat kode ini, kita perlu mengganti MIN_US dan FACTOR dengan ambang penundaan dan satuan waktu, yang akan kita lewati argumennya:
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 mempersiapkan program BPF melalui dan daftarkan 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 menentukannya struct data_t dalam skrip kami, jika tidak, kami tidak akan dapat membaca apa pun:
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 adalah 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()
Scriptnya sendiri tersedia di . Mari kita coba menjalankannya pada platform pengujian tempat fio berjalan, menulis ke bcache, dan memanggil monitor udevadm:
Akhirnya! Sekarang kita melihat bahwa apa yang tampak seperti perangkat bcache yang terhenti sebenarnya adalah panggilan yang terhenti permintaan_pembuatan_generik() untuk disk yang di-cache.
Gali ke dalam Kernel
Apa sebenarnya yang melambat selama transmisi permintaan? Kami melihat bahwa penundaan terjadi bahkan sebelum dimulainya penghitungan permintaan, mis. penghitungan permintaan khusus untuk keluaran statistik lebih lanjut di dalamnya (/proc/diskstats atau iostat) belum dimulai. Hal ini dapat dengan mudah diverifikasi dengan menjalankan iostat sambil mereproduksi masalah, atau , yang didasarkan pada awal dan akhir akuntansi permintaan. Tak satu pun dari utilitas ini akan menunjukkan masalah permintaan ke disk yang di-cache.
Jika kita melihat fungsinya permintaan_pembuatan_generik(), maka kita akan melihat bahwa sebelum permintaan mulai dihitung, dua fungsi lagi dipanggil. Pertama - generik_make_request_checks(), melakukan pemeriksaan terhadap keabsahan permintaan mengenai pengaturan disk. Kedua - , yang memiliki tantangan 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 antrian mencair. Mari kita ukur penundaannya 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 | |
Sepertinya kita hampir mencapai solusi. Fungsi yang digunakan untuk membekukan/mencairkan antrian adalah ΠΈ . Mereka digunakan ketika diperlukan untuk mengubah pengaturan antrean permintaan, yang berpotensi berbahaya untuk permintaan dalam antrean ini. Saat menelepon blk_mq_freeze_queue() fungsi penghitungnya bertambah q->mq_freeze_kedalaman. Setelah ini, kernel menunggu antrian kosong .
Waktu yang diperlukan untuk menghapus antrean ini setara dengan latensi disk saat kernel menunggu hingga semua operasi antrean selesai. Setelah antrian kosong, perubahan pengaturan diterapkan. Setelah itu dipanggil , mengurangi penghitung bekukan_kedalaman.
Sekarang kami cukup tahu untuk memperbaiki situasi. Perintah pemicu udevadm menyebabkan pengaturan untuk perangkat blok diterapkan. Pengaturan ini dijelaskan dalam aturan udev. Kita dapat menemukan pengaturan mana yang membekukan antrian dengan mencoba mengubahnya melalui sysfs atau dengan melihat kode sumber kernel. Kami juga dapat mencoba utilitas BCC , yang akan menampilkan jejak tumpukan kernel dan ruang pengguna untuk setiap panggilan ke terminal blk_freeze_queue, misalnya:
~# /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]
Aturan Udev jarang berubah dan biasanya hal ini terjadi secara terkendali. Jadi kita melihat bahwa penerapan nilai yang sudah ditetapkan menyebabkan lonjakan penundaan dalam mentransfer permintaan dari aplikasi ke disk. Tentu saja, membuat event udev ketika tidak ada perubahan pada konfigurasi disk (misalnya, perangkat tidak dipasang/diputuskan) bukanlah praktik yang baik. Namun, kami dapat membantu kernel untuk tidak melakukan pekerjaan yang tidak perlu dan membekukan antrian permintaan jika tidak diperlukan. memperbaiki situasi.
Kesimpulan
eBPF adalah alat yang sangat fleksibel dan kuat. Dalam artikel tersebut kami melihat satu kasus praktis dan mendemonstrasikan sebagian kecil dari apa yang dapat dilakukan. Jika Anda tertarik untuk mengembangkan utilitas BCC, ada baiknya Anda melihatnya , yang menjelaskan dasar-dasarnya dengan baik.
Ada alat debugging dan pembuatan profil menarik lainnya berdasarkan eBPF. Salah satu diantara mereka - , yang memungkinkan Anda menulis satu kalimat yang kuat dan program kecil dalam bahasa mirip awk. Lain - , memungkinkan Anda mengumpulkan metrik tingkat rendah dan resolusi tinggi langsung ke server prometheus Anda, dengan kemampuan untuk kemudian mendapatkan visualisasi yang indah dan bahkan peringatan.
Sumber: www.habr.com