Linux, çekirdekte ve uygulamalarda hata ayıklamak için çok sayıda araca sahiptir. Çoğunun uygulama performansı üzerinde olumsuz etkisi vardır ve üretimde kullanılamaz.
Birkaç yıl önce vardı - eBPF. Düşük ek yük ile ve programları yeniden oluşturmaya ve üçüncü taraf modülleri çekirdeğe yüklemeye gerek kalmadan çekirdek ve kullanıcı uygulamalarının izlenmesini mümkün kılar.
Zaten eBPF'yi kullanan birçok uygulama yardımcı programı var ve bu makalede kitaplığa dayalı olarak kendi profil oluşturma yardımcı programınızı nasıl yazacağınıza bakacağız. . Makale gerçek olaylara dayanmaktadır. Mevcut yardımcı programların belirli durumlarda nasıl kullanılabileceğini göstermek için sorundan çözüme geçeceğiz.
Ceph Yavaş
Ceph kümesine yeni bir ana bilgisayar eklendi. Verilerin bir kısmını bu sunucuya aktardıktan sonra, yazma isteklerini işleme hızının diğer sunuculara göre çok daha düşük olduğunu fark ettik.
Diğer platformların aksine, bu sunucu bcache'i ve yeni linux 4.15 çekirdeğini kullanıyordu. Bu, bu yapılandırmaya sahip bir ana bilgisayarın burada kullanıldığı ilk seferdi. Ve o anda sorunun kökeninin teorik olarak herhangi bir şey olabileceği açıktı.
Ev Sahibinin Araştırılması
Ceph-osd sürecinde neler olduğuna bakarak başlayalım. Bunun için kullanacağız и (okuyabileceğiniz hakkında daha fazla bilgi ):
Resim bize fonksiyonun fdatasync() işlevlere istek göndermek için çok zaman harcadım general_make_request(). Bu, büyük olasılıkla sorunların nedeninin osd arka plan programının dışında bir yerde olduğu anlamına gelir. Bu çekirdek veya diskler olabilir. Iostat çıktısı, bcache diskleri tarafından isteklerin işlenmesinde yüksek bir gecikme olduğunu gösterdi.
Ana bilgisayarı kontrol ederken, systemd-udevd arka plan programının büyük miktarda CPU zamanı tükettiğini gördük - birkaç çekirdekte yaklaşık %20. Bu garip bir davranış, bu yüzden nedenini bulmanız gerekiyor. Systemd-udevd olaylarla çalıştığından, onlara şöyle bakmaya karar verdik: udevadm monitör. Sistemdeki her blok cihaz için çok sayıda değişiklik olayının üretildiği ortaya çıktı. Bu oldukça alışılmadık bir durum, dolayısıyla tüm bu olayları neyin oluşturduğuna bakmamız gerekecek.
BCC Araç Setini Kullanma
Daha önce de öğrendiğimiz gibi, çekirdek (ve sistem çağrısındaki ceph arka plan programı) çok fazla zaman harcıyor. general_make_request(). Bu fonksiyonun hızını ölçmeye çalışalım. İÇİNDE Zaten harika bir yardımcı program var - eğlence. Çıkışlar arasında 1 saniyelik bir aralıkla arka plan programını PID'sine göre takip edeceğiz ve sonucu milisaniye cinsinden çıktı olarak alacağız.
Bu özellik genellikle hızlı çalışır. Tek yaptığı, isteği aygıt sürücüsü kuyruğuna iletmektir.
önbellek aslında üç diskten oluşan karmaşık bir cihazdır:
- yedekleme aygıtı (önbelleğe alınmış disk), bu durumda yavaş bir HDD'dir;
- önbellekleme aygıtı (önbellekleme diski), burada bu NVMe aygıtının bir bölümüdür;
- uygulamanın çalıştığı bcache sanal cihazı.
İstek iletiminin yavaş olduğunu biliyoruz ama bu cihazlardan hangisi için? Bu konuyu biraz sonra ele alacağız.
Artık olayların sorunlara neden olabileceğini biliyoruz. Oluşumlarına tam olarak neyin sebep olduğunu bulmak o kadar kolay değil. Bunun periyodik olarak başlatılan bir tür yazılım olduğunu varsayalım. Bir betik kullanarak sistemde ne tür bir yazılımın çalıştığını görelim yöneticisnoop aynısından . Çalıştıralım ve çıktıyı bir dosyaya gönderelim.
Örneğin, bunun gibi:
/usr/share/bcc/tools/execsnoop | tee ./execdump
Burada execsnoop'un tam çıktısını göstermeyeceğiz, ancak ilgimizi çeken bir satır şöyle görünüyordu:
sh 1764905 5802 0 sudo arcconf getconfig 1 AD | grep Temperature | awk -F '[:/]' '{print $2}' | sed 's/^ ([0-9]*) C.*/1/'
Üçüncü sütun sürecin PPID'sidir (ana PID). PID 5802'ye sahip sürecin, izleme sistemimizin iş parçacıklarından biri olduğu ortaya çıktı. İzleme sisteminin konfigürasyonunu kontrol ederken hatalı parametreler bulundu. HBA adaptörünün sıcaklığı her 30 saniyede bir ölçülüyordu; bu da gereğinden çok daha sık bir ölçümdü. Kontrol aralığını daha uzun bir aralıkla değiştirdikten sonra, bu ana bilgisayardaki istek işleme gecikmesinin artık diğer ana bilgisayarlarla karşılaştırıldığında göze çarpmadığını gördük.
Ancak bcache cihazının neden bu kadar yavaş olduğu hala belli değil. Aynı konfigürasyona sahip bir test platformu hazırladık ve fio'yu bcache üzerinde çalıştırarak, udevadm tetikleyicisini periyodik olarak çalıştırarak olay oluşturma işlemini gerçekleştirerek sorunu yeniden oluşturmaya çalıştık.
BCC Tabanlı Araçlar Yazma
En yavaş aramaları izlemek ve görüntülemek için basit bir yardımcı program yazmaya çalışalım general_make_request(). Bu işlevin çağrıldığı sürücünün adıyla da ilgileniyoruz.
Plan basit:
- Kayıt olmak kprobe üzerinde general_make_request():
- Disk adını, işlev argümanı aracılığıyla erişilebilen belleğe kaydederiz;
- Zaman damgasını kaydediyoruz.
- Kayıt olmak kretprobe dönüş için general_make_request():
- Geçerli zaman damgasını alıyoruz;
- Kaydedilen zaman damgasını ararız ve mevcut olanla karşılaştırırız;
- Sonuç belirtilenden büyükse, kaydedilen disk adını bulur ve terminalde görüntüleriz.
Kprobe'lar и kretprobe'lar anında işlev kodunu değiştirmek için bir kesme noktası mekanizması kullanın. Okuyabilirsin и Bu konuyla ilgili makale. Çeşitli yardımcı programların koduna bakarsanız , o zaman aynı yapıya sahip olduklarını görebilirsiniz. Dolayısıyla bu makalede komut dosyası argümanlarını ayrıştırmayı atlayıp BPF programının kendisine geçeceğiz.
Python betiğinin içindeki eBPF metni şuna benzer:
bpf_text = “”” # Here will be the bpf program code “””
İşlevler arasında veri alışverişi yapmak için eBPF programları şunları kullanır: . Biz de aynısını yapacağız. İşlem PID'sini anahtar olarak kullanacağız ve yapıyı değer olarak tanımlayacağız:
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);
Burada adı verilen bir karma tablosunu kaydediyoruz. p, anahtar tipiyle u64 ve bir tür değeri data_t yapısı. Tablo BPF programımız kapsamında mevcut olacaktır. BPF_PERF_OUTPUT makrosu, adı verilen başka bir tabloyu kaydeder. olaylariçin kullanılan kullanıcı alanına.
Bir işlevin çağrılması ile ondan geri dönüş arasındaki veya farklı işlevlere yapılan çağrılar arasındaki gecikmeleri ölçerken, alınan verilerin aynı bağlama ait olması gerektiğini dikkate almanız gerekir. Başka bir deyişle, işlevlerin olası paralel başlatılmasını hatırlamanız gerekir. Bir işlemin bağlamında bir işlevi çağırmak ile başka bir işlemin bağlamında o işlevden geri dönmek arasındaki gecikmeyi ölçme yeteneğine sahibiz, ancak bu muhtemelen işe yaramaz. Burada iyi bir örnek olabilir karma tablosu anahtarının bir işaretçiye ayarlandığı yer yapı isteği, bir disk isteğini yansıtır.
Daha sonra, incelenen fonksiyon çağrıldığında çalışacak kodu yazmamız gerekiyor:
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);
}
Burada çağrılan fonksiyonun ilk argümanı ikinci argüman olarak değiştirilecektir. . Bundan sonra, çalıştığımız bağlamdaki sürecin PID'sini ve nanosaniye cinsinden güncel zaman damgasını alıyoruz. Hepsini yeni seçilmiş bir kağıda yazıyoruz. data_t verilerini yapılandır. Disk adını yapıdan alıyoruz bio, çağrılırken iletilen general_make_request()ve aynı yapıya kaydedin veri. Son adım, daha önce bahsedilen karma tablosuna bir giriş eklemektir.
Dönüşte aşağıdaki fonksiyon çağrılacak general_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);
}
}
Bu işlev öncekine benzer: Sürecin PID'sini ve zaman damgasını buluruz, ancak yeni veri yapısı için bellek ayırmayız. Bunun yerine, == geçerli PID anahtarını kullanarak karma tablosunda zaten var olan bir yapıyı ararız. Yapı bulunursa, çalışan sürecin adını bulup ona ekliyoruz.
Burada kullandığımız ikili kaydırma, iş parçacığı GID'sini almak için gereklidir. onlar. Üzerinde çalıştığımız bağlamda konuyu başlatan ana sürecin PID'si. Çağırdığımız fonksiyon hem iş parçacığının GID'sini hem de PID'sini tek bir 64 bitlik değerde döndürür.
Terminale çıktı verirken, şu anda iş parçacığıyla ilgilenmiyoruz, ancak ana süreçle ilgileniyoruz. Ortaya çıkan gecikmeyi belirli bir eşikle karşılaştırdıktan sonra yapımızı geçiyoruz veri tablo aracılığıyla kullanıcı alanına olaylar, bundan sonra girişi sileriz p.
Bu kodu yükleyecek python betiğinde MIN_US ve FACTOR'u argümanlardan geçireceğimiz gecikme eşikleri ve zaman birimleriyle değiştirmemiz gerekiyor:
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"
Şimdi BPF programını şu şekilde hazırlamamız gerekiyor: ve örnekleri kaydedin:
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")
Ayrıca belirlememiz gerekecek data_t yapısı senaryomuzda, aksi halde hiçbir şey okuyamayız:
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)]
Son adım terminale veri çıkışı yapmaktır:
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()
Komut dosyasının kendisi şu adreste mevcuttur: . Fio'nun çalıştığı bir test platformunda çalıştırmayı deneyelim, bcache'e yazalım ve udevadm monitörünü çağıralım:
Nihayet! Artık, durmuş bir önbellek cihazı gibi görünen şeyin aslında oyalanmış bir çağrı olduğunu görüyoruz general_make_request() önbelleğe alınmış bir disk için.
Çekirdeği kazın
İstek iletimi sırasında tam olarak yavaşlayan şey nedir? Gecikmenin, talep muhasebesinin başlamasından önce bile meydana geldiğini görüyoruz, yani. bununla ilgili daha fazla istatistik çıktısı alınmasına yönelik özel bir talebin muhasebeleştirilmesi (/proc/diskstats veya iostat) henüz başlamadı. Bu, sorunu yeniden oluştururken iostat çalıştırılarak kolayca doğrulanabilir veya , istek muhasebesinin başlangıcını ve bitişini temel alır. Bu yardımcı programların hiçbiri önbelleğe alınan diske yapılan isteklerde sorun göstermez.
Fonksiyona bakarsak general_make_request(), o zaman isteğin muhasebeye başlamasından önce iki işlevin daha çağrıldığını göreceğiz. Birinci - general_make_request_checks(), disk ayarlarına ilişkin talebin meşruiyetine ilişkin kontrolleri gerçekleştirir. Saniye - ilginç bir zorluğu olan :
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));
İçinde çekirdek, sıranın çözülmesini bekler. Gecikmeyi ölçelim 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 | |
Çözüme yakınız gibi görünüyor. Bir kuyruğu dondurmak/çözmek için kullanılan işlevler şunlardır: и . Bu kuyruktaki istekler için potansiyel olarak tehlikeli olan istek kuyruğu ayarlarının değiştirilmesi gerektiğinde kullanılırlar. Ararken blk_mq_freeze_queue() işlevi sayaç artırılır q->mq_freeze_derinlik. Bundan sonra çekirdek kuyruğun boşalmasını bekler. .
Bu kuyruğu temizlemek için gereken süre, çekirdeğin sıraya alınmış tüm işlemlerin tamamlanmasını beklediği disk gecikmesine eşdeğerdir. Kuyruk boşaldığında ayar değişiklikleri uygulanır. Bundan sonra denir , sayacın azaltılması dondurma_derinliği.
Artık durumu düzeltmeye yetecek kadar bilgimiz var. Udevadm tetikleme komutu, blok cihazının ayarlarının uygulanmasına neden olur. Bu ayarlar udev kurallarında açıklanmıştır. Hangi ayarların kuyruğu dondurduğunu sysfs üzerinden değiştirmeyi deneyerek veya çekirdek kaynak koduna bakarak bulabiliriz. BCC yardımcı programını da deneyebiliriz terminale yapılan her çağrı için çekirdek ve kullanıcı alanı yığın izlerinin çıktısını alacak blk_freeze_queueÖrneğin:
~# /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]
Udev kuralları oldukça nadiren değişir ve bu genellikle kontrollü bir şekilde gerçekleşir. Böylece, önceden ayarlanmış değerlerin uygulanmasının bile, isteğin uygulamadan diske aktarılmasında gecikmede ani bir artışa neden olduğunu görüyoruz. Elbette, disk konfigürasyonunda herhangi bir değişiklik olmadığında (örneğin, cihaz monte edilmemiş/bağlantısı kesilmemişken) udev olayları oluşturmak iyi bir uygulama değildir. Ancak çekirdeğin gereksiz işler yapmamasına ve gerekmediği takdirde istek kuyruğunu dondurmasına yardımcı olabiliriz. durumu düzeltin.
Sonuç
eBPF çok esnek ve güçlü bir araçtır. Makalede pratik bir duruma baktık ve neler yapılabileceğinin küçük bir kısmını gösterdik. BCC yardımcı programlarını geliştirmekle ilgileniyorsanız, şu adrese göz atmaya değer: , temelleri iyi açıklıyor.
eBPF'yi temel alan başka ilginç hata ayıklama ve profil oluşturma araçları da vardır. Onlardan biri - awk benzeri bir dilde güçlü tek satırlık satırlar ve küçük programlar yazmanıza olanak tanır. Bir diğer - , daha sonra güzel görselleştirmeler ve hatta uyarılar alabilme yeteneğiyle, düşük seviyeli, yüksek çözünürlüklü ölçümleri doğrudan prometheus sunucunuzda toplamanıza olanak tanır.
Kaynak: habr.com