W systemie Linux istnieje wiele narzędzi do debugowania jądra i aplikacji. Większość z nich negatywnie wpływa na wydajność aplikacji i nie może być używana w produkcji.
Kilka lat temu opracowano jeszcze jedno narzędzie Obecnie istnieje wiele aplikacji, które wykorzystują eBPF, a w tym artykule przyjrzymy się, jak napisać własne narzędzie do profilowania w oparciu o bibliotekę
PythonBCC Ceph jest powolny
Do klastra Ceph dodano nowy host. Po migracji części danych na niego zauważyliśmy, że prędkość przetwarzania zapytań do zapisu jest znacznie niższa niż na innych serwerach.
W przeciwieństwie do innych platform, na tym hoście używano bcache oraz nowego jądra Linux 4.15. Taka konfiguracja hosta była tu stosowana po raz pierwszy. I wówczas było jasne, że źródłem problemu teoretycznie mogło być cokolwiek.
Badanie hosta
Zaczniemy od przyjrzenia się temu, co dzieje się wewnątrz procesu ceph-osd. W tym celu skorzystamy z
flamescope i Obrazek mówi nam, że funkcja ):
spędziła dużo czasu przy wysyłaniu zapytania w funkcji fdatasync() generic_make_request() . To oznacza, że prawdopodobnie przyczyna problemów leży gdzieś poza samym demonem osd. Może to być albo jądro, albo dyski. Wyjście z iostat pokazywało wysokie opóźnienie w przetwarzaniu zapytań przez dyski bcache.Podczas sprawdzania hosta odkryliśmy, że demon systemd-udevd zużywa dużą ilość czasu CPU — około 20% na kilku rdzeniach. To dziwne zachowanie, więc należy ustalić jego przyczynę. Ponieważ systemd-udevd działa z ueventami, postanowiliśmy przyjrzeć się nim przez
udevadm monitor . Okazało się, że generowano dużą liczbę wydarzeń zmiany dla każdego bloku urządzenia w systemie. To dość niezwykłe, więc trzeba będzie sprawdzić, co generuje te wszystkie zdarzenia.Korzystanie z zestawu narzędzi BCC
Jak już ustaliliśmy, jądro (oraz demon ceph w wywołaniu systemowym) spędza dużo czasu w
. Spróbujemy zmierzyć czas działania tej funkcji. W . To oznacza, że prawdopodobnie przyczyna problemów leży gdzieś poza samym demonem osd. Może to być albo jądro, albo dyski. Wyjście z iostat pokazywało wysokie opóźnienie w przetwarzaniu zapytań przez dyski bcache.BCC funclatency funkcjonalne opóźnienie. Będziemy śledzić demona po jego PID z interwałem 1 sekundy między informacjami i wyświetlimy wynik w milisekundach.
Zazwyczaj ta funkcja działa szybko. Wszystko, co robi, to przekazuje żądanie do kolejki sterownika urządzenia.
Bcache — to złożone urządzenie, które tak naprawdę składa się z trzech dysków:
- device backing (dysk buforowany), w tym przypadku to wolny HDD;
- device caching (dysk buforujący), w tym przypadku to jedna partycja urządzenia NVMe;
- wirtualne urządzenie bcache, z którym pracuje aplikacja.
Wiemy, że przekazywanie żądania spowalnia, ale dla którego z tych urządzeń? Zrozumiemy to trochę później.
Teraz wiemy, że ueventy prawdopodobnie powodują problemy. Znalezienie, co dokładnie je generuje, nie jest takie proste. Załóżmy, że to jakiś program uruchamiany okresowo. Sprawdzimy, jaki program uruchamia się w systemie, za pomocą skryptu execsnoop z tego samego . Uruchomimy go i skierujemy wyjście do pliku.
Na przykład tak:
/usr/share/bcc/tools/execsnoop | tee ./execdump
Nie będziemy tutaj podawać pełnego wyjścia execsnoop, ale jedna interesująca nas linia wyglądała tak:
sh 1764905 5802 0 sudo arcconf getconfig 1 AD | grep Temperature | awk -F '[:\/]' '{print $2}' | sed 's\/^ ([0-9]*) C.*\/1\/'
Trzecia kolumna to PPID (PID rodzica) procesu. Proces o PID 5802 okazał się jednym z wątków naszego systemu monitorowania. Podczas sprawdzania konfiguracji systemu monitorowania znaleziono błędnie ustawione parametry. Temperatura adaptera HBA była odczytywana co 30 sekund, co było znacznie za często. Po zmianie interwału sprawdzania na dłuższy, zauważyliśmy, że opóźnienie przetwarzania żądań na tym hoście przestało być widoczne na tle innych hostów.
Ale wciąż nie wiadomo, dlaczego urządzenie bcache tak spowalniało. Przygotowaliśmy platformę testową o identycznej konfiguracji i spróbowaliśmy odtworzyć problem, uruchamiając fio na bcache, okresowo uruchamiając udevadm trigger w celu generowania uevents.
Pisanie narzędzi opartych na BCC
Spróbujemy napisać prostą usługę do śledzenia i wyświetlania na ekranie najbardziej wolnych wywołań . To oznacza, że prawdopodobnie przyczyna problemów leży gdzieś poza samym demonem osd. Może to być albo jądro, albo dyski. Wyjście z iostat pokazywało wysokie opóźnienie w przetwarzaniu zapytań przez dyski bcache.. Interesuje nas również nazwa dysku, dla którego ta funkcja została wywołana.
Plan jest prosty:
- Rejestrujemy kprobe na . To oznacza, że prawdopodobnie przyczyna problemów leży gdzieś poza samym demonem osd. Może to być albo jądro, albo dyski. Wyjście z iostat pokazywało wysokie opóźnienie w przetwarzaniu zapytań przez dyski bcache.:
- Zapisujemy w pamięci nazwę dysku dostępną przez argument funkcji;
- Zapisujemy znacznik czasu.
- Rejestrujemy kretprobe na powrocie z . To oznacza, że prawdopodobnie przyczyna problemów leży gdzieś poza samym demonem osd. Może to być albo jądro, albo dyski. Wyjście z iostat pokazywało wysokie opóźnienie w przetwarzaniu zapytań przez dyski bcache.:
- Pobieramy bieżący znacznik czasu;
- Szukamy zapisanego znacznika czasu i porównujemy go z bieżącym;
- Jeśli wynik jest większy od podanego, odszukujemy zapisane imię dysku i wyświetlamy je w terminalu.
Kprobes i kretprobes używają mechanizmu punktów zatrzymania do dynamicznej zmiany kodu funkcji. Możesz przeczytać i artykuł na ten temat. Jeśli przyjrzymy się kodowi różnych narzędzi w , to można zauważyć, że mają one identyczną strukturę. W związku z tym w tym artykule pominujemy analizę argumentów skryptu i przechodzimy do samego programu BPF.
Tekst eBPF wewnątrz skryptu python wygląda następująco:
bpf_text = ''' # Tutaj będzie kod programu bpf '''
Do wymiany danych pomiędzy funkcjami, programy eBPF wykorzystują . My również tak zrobimy. Jako klucz wykorzystamy PID procesu, a jako wartość zdefiniujemy 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);
Tutaj rejestrujemy tabelę hash, która nazywa się p, z kluczem typu u64 i wartością typu struct data_t. Tabela będzie dostępna w kontekście naszego programu BPF. Makros BPF_PERF_OUTPUT rejestruje inną tabelę, nazwaną events, która jest używana do do przestrzeni użytkownika.
Podczas pomiaru opóźnień między wywołaniem funkcji a zwrotem z niej, lub między wywołaniami różnych funkcji, trzeba pamiętać, że otrzymane dane powinny należeć do jednego kontekstu. Innymi słowy, należy pamiętać o możliwym równoległym uruchamianiu funkcji. Możemy zmierzyć opóźnienie między wywołaniem funkcji w kontekście jednego procesu, a zwrotem z tej funkcji w kontekście innego procesu, ale to prawdopodobnie nie będzie użyteczne. Dobrym przykładem może być , gdzie jako klucz tabeli hash ustawiany jest wskaźnik na struct request, który odzwierciedla jedno zapytanie do dysku.
Następnie musimy napisać kod, który będzie wykonywany przy wywołaniu badanej funkcji:
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);
}
Tutaj jako drugi argument zostanie podstawiony pierwszy argument wywołanej funkcji . Po tym uzyskujemy PID procesu, w kontekście którego pracujemy, oraz bieżący znacznik czasu w nanosekundach. Zapisujemy to wszystko w świeżo przydzielonym struct data_t data. Nazwę dysku uzyskujemy ze struktury bio, który jest przekazywany podczas wezwania . To oznacza, że prawdopodobnie przyczyna problemów leży gdzieś poza samym demonem osd. Może to być albo jądro, albo dyski. Wyjście z iostat pokazywało wysokie opóźnienie w przetwarzaniu zapytań przez dyski bcache., i przechowujemy go w tej samej strukturze data. Ostatnim krokiem jest dodanie rekordu do tabeli haszowej, o której mówiono wcześniej.
Następna funkcja będzie wywoływana po zwrocie z . To oznacza, że prawdopodobnie przyczyna problemów leży gdzieś poza samym demonem osd. Może to być albo jądro, albo dyski. Wyjście z iostat pokazywało wysokie opóźnienie w przetwarzaniu zapytań przez dyski bcache.:
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);
}
}
Ta funkcja jest podobna do poprzedniej: uzyskujemy PID procesu i znacznik czasu, ale nie przydzielamy pamięci pod nową strukturę data. Zamiast tego szukamy w tabeli haszowej już istniejącej struktury o kluczu == bieżący PID. Jeśli struktura została znaleziona, to uzyskujemy nazwę uruchomionego procesu i dodajemy ją do niej.
Przesunięcie binarne, które stosujemy tutaj, jest potrzebne, aby uzyskać GID wątku, tzn. PID głównego procesu, który uruchomił wątek, w kontekście, w którym pracujemy. Wywołujemy funkcję zwraca zarówno GID wątku, jak i jego PID w jednej wartości 64-bitowej.
Podczas wyjścia na terminal obecnie nie interesuje nas wątek, ale interesuje nas główny proces. Po porównaniu uzyskanej opóźnienia z ustalonym progiem, przekazujemy naszą strukturę data do przestrzeni użytkownika przez tabelę events, po czym usuwamy wpis z p.
W skrypcie Pythona, który załaduje ten kod, musimy zastąpić MIN_US i FACTOR progami opóźnienia i jednostek czasu, które przekażemy przez argumenty:
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"
Teraz musimy przygotować program BPF poprzez i zarejestrować próbki:
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")
Musimy również zdefiniować struct data_t w naszym skrypcie, inaczej nic nie będziemy mogli odczytać:
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)]
Ostatnim krokiem jest wypisanie danych na terminalu:
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()
Sam skrypt jest dostępny na . Spróbujemy uruchomić go na platformie testowej, na której działa fio piszące na bcache, i wywołać monitor udevadm:
Wreszcie! Teraz widzimy, że to, co wyglądało jak spowalniające urządzenie bcache, tak naprawdę jest spowalniającym wywołaniem . To oznacza, że prawdopodobnie przyczyna problemów leży gdzieś poza samym demonem osd. Może to być albo jądro, albo dyski. Wyjście z iostat pokazywało wysokie opóźnienie w przetwarzaniu zapytań przez dyski bcache. dla dysku buforowanego.
Zagłębiamy się w jądro
Co dokładnie spowalnia podczas przesyłania żądania? Widzimy, że opóźnienie występuje nawet przed rozpoczęciem rozliczania żądania, tzn. liczenie konkretnego żądania dla dalszego wyświetlania statystyk (/ proc/diskstats lub iostat) jeszcze się nie rozpoczęło. Można to łatwo sprawdzić, uruchamiając iostat podczas odtwarzania problemu lub , który opiera się na początku i końcu rozliczania żądań. Żadne z tych narzędzi nie wskaże problemów z żądaniami do buforowanego dysku.
Jeśli spojrzymy na funkcję . To oznacza, że prawdopodobnie przyczyna problemów leży gdzieś poza samym demonem osd. Może to być albo jądro, albo dyski. Wyjście z iostat pokazywało wysokie opóźnienie w przetwarzaniu zapytań przez dyski bcache., zauważymy, że przed rozpoczęciem rozliczania żądania wywoływane są jeszcze dwie funkcje. Pierwsza to generic_make_request_checks(), która wykonuje weryfikację legalności żądania w odniesieniu do ustawień dysku. Druga to , w której znajduje się interesujące wywołanie :
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));
W nim jądro czeka na rozmrożenie kolejki. Zmierzmy opóźnienie blk_queue_enter():
~# /usr/share/bcc/tools/funclatency blk_queue_enter -i 1 -m
Śledzenie 1 funkcji dla "blk_queue_enter"... Naciśnij Ctrl-C, aby zakończyć.
msecs : count dystrybucja
0 -> 1 : 341 |****************************************|
msecs : count dystrybucja
0 -> 1 : 316 |****************************************|
msecs : count dystrybucja
0 -> 1 : 255 |****************************************|
2 -> 3 : 0 | |
4 -> 7 : 0 | |
8 -> 15 : 1 | |
Wygląda na to, że jesteśmy blisko rozwiązania. Funkcje używane do "zamrażania/rozmrażania" kolejki to i . Używane są, gdy trzeba zmienić ustawienia kolejki żądań, które mogą być niebezpieczne dla żądań znajdujących się w tej kolejce. Przy wywołaniu blk_mq_freeze_queue() funkcja inkrementuje licznik q->mq_freeze_depth. Po tym jądrze czeka na opróżnienie kolejki w .
Czas oczekiwania na opróżnienie tej kolejki jest równoważny opóźnieniu dysku, ponieważ jądro czeka na zakończenie wszystkich operacji w kolejce. Gdy kolejka jest pusta, zastosowane zostają zmiany w ustawieniach. Następnie wywoływana jest , dekrementując licznik freeze_depth.
Teraz mamy wystarczająco dużo informacji, aby poprawić sytuację. Komenda udevadm trigger prowadzi zatem do zastosowania ustawień dla urządzenia blokowego. Ustawienia te opisane są w regułach udev. Możemy sprawdzić, które ustawienia 'zamrażają' kolejkę, próbując je zmienić przez sysfs lub przeglądając kod źródłowy jądra. Możemy także użyć narzędzia BCC , które wyświetli na terminalu ślady stosu jądra i przestrzeni użytkownika dla każdego wywołania blk_freeze_queue, na przykład:
~# /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 [jądro]
elevator_switch+0x29 [jądro]
elv_iosched_store+0x197 [jądro]
queue_attr_store+0x5c [jądro]
sysfs_kf_write+0x3c [jądro]
kernfs_fop_write+0x125 [jądro]
__vfs_write+0x1b [jądro]
vfs_write+0xb8 [jądro]
sys_write+0x55 [jądro]
do_syscall_64+0x73 [jądro]
entry_SYSCALL_64_after_hwframe+0x3d [jądro]
__write_nocancel+0x7 [libc-2.23.so]
[nierozpoznane]
3809631 3809631 systemd-udevd blk_freeze_queue
blk_freeze_queue+0x1 [jądro]
queue_requests_store+0xb6 [jądro]
queue_attr_store+0x5c [jądro]
sysfs_kf_write+0x3c [jądro]
kernfs_fop_write+0x125 [jądro]
__vfs_write+0x1b [jądro]
vfs_write+0xb8 [jądro]
sys_write+0x55 [jądro]
do_syscall_64+0x73 [jądro]
entry_SYSCALL_64_after_hwframe+0x3d [jądro]
__write_nocancel+0x7 [libc-2.23.so]
[nierozpoznane]
Reguły udev zmieniają się dość rzadko i zazwyczaj odbywa się to pod kontrolą. Widzimy więc, że nawet zastosowanie już zadanych wartości wywołuje wzrost opóźnienia przesyłu żądania od aplikacji do dysku. Oczywiście generowanie wydarzeń udev, gdy nie ma żadnych zmian w konfiguracji dysków (np. urządzenie nie jest podłączane/odłączane), to nie najlepsza praktyka. Niemniej jednak możemy pomóc jądrze nie wykonywać zbędnej pracy i nie 'zamrażać' kolejki żądań, jeśli nie ma takiej konieczności. poprawiają sytuację.
Podsumowanie
eBPF to bardzo elastyczne i potężne narzędzie. W artykule omówiliśmy jeden przypadek zastosowania i zaprezentowaliśmy niewielką część tego, co można zrobić. Jeśli interesuje Cię rozwój narzędzi BCC, warto rzucić okiem na , który dobrze opisuje podstawy działania.
Istnieją również inne interesujące narzędzia do debugowania i profilowania oparte na eBPF. Jednym z nich jest , które pozwala na pisanie potężnych skryptów jednowierszowych i małych programów w języku podobnym do awk. Drugie z nich to , które umożliwia zbieranie niskopoziomowych metryk o wysokiej rozdzielczości bezpośrednio na twoim serwerze prometheus, z możliwością późniejszej wizualizacji i nawet alertów.
Źródło: habr.com
